Cast channel logging: log additional statistics.

- bytes read / written per socket
- total bytes read / written across all sockets

Also changed the Logger class to hold a Log proto instead of individual
fields.

BUG=343228

Review URL: https://codereview.chromium.org/475463002

Cr-Commit-Position: refs/heads/master@{#290009}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@290009 0039d316-1c4b-4281-b951-d872f2087c98

extensions/browser/api/cast_channel/cast_socket.cc

@@ -715,8 +715,9 @@ int CastSocket::DoWriteComplete(int result) {
 
 int CastSocket::DoWriteCallback() {
   DCHECK(!write_queue_.empty());
-  write_state_ = WRITE_STATE_WRITE;
-  logger_->LogSocketWriteState(channel_id_, WriteStateToProto(write_state_));
+
+  SetWriteState(WRITE_STATE_WRITE);
+
   WriteRequest& request = write_queue_.front();
   int bytes_consumed = request.io_buffer->BytesConsumed();
   logger_->LogSocketEventForMessage(

extensions/browser/api/cast_channel/logger.cc

@@ -108,10 +108,7 @@ Logger::AggregatedSocketEventLog::~AggregatedSocketEventLog() {
 
 Logger::Logger(scoped_ptr<base::TickClock> clock,
                base::TimeTicks unix_epoch_time_ticks)
-    : clock_(clock.Pass()),
-      unix_epoch_time_ticks_(unix_epoch_time_ticks),
-      num_evicted_aggregated_socket_events_(0),
-      num_evicted_socket_events_(0) {
+    : clock_(clock.Pass()), unix_epoch_time_ticks_(unix_epoch_time_ticks) {
   DCHECK(clock_);
 
   // Logger may not be necessarily be created on the IO thread, but logging
@@ -127,11 +124,9 @@ void Logger::LogNewSocketEvent(const CastSocket& cast_socket) {
 
   int channel_id = cast_socket.id();
   SocketEvent event = CreateEvent(proto::CAST_SOCKET_CREATED);
-  LogSocketEvent(channel_id, event);
-
   AggregatedSocketEvent& aggregated_socket_event =
-      aggregated_socket_events_.find(channel_id)
-          ->second->aggregated_socket_event;
+      LogSocketEvent(channel_id, event);
+
   const net::IPAddressNumber& ip = cast_socket.ip_endpoint().address();
   aggregated_socket_event.set_endpoint_id(ip.back());
   aggregated_socket_event.set_channel_auth_type(cast_socket.channel_auth() ==
@@ -166,7 +161,19 @@ void Logger::LogSocketEventWithRv(int channel_id,
   SocketEvent event = CreateEvent(event_type);
   event.set_net_return_value(rv);
 
-  LogSocketEvent(channel_id, event);
+  AggregatedSocketEvent& aggregated_socket_event =
+      LogSocketEvent(channel_id, event);
+
+  if ((event_type == proto::SOCKET_READ || event_type == proto::SOCKET_WRITE) &&
+      rv > 0) {
+    if (event_type == proto::SOCKET_READ) {
+      aggregated_socket_event.set_bytes_read(
+          aggregated_socket_event.bytes_read() + rv);
+    } else {
+      aggregated_socket_event.set_bytes_written(
+          aggregated_socket_event.bytes_written() + rv);
+    }
+  }
 }
 
 void Logger::LogSocketReadyState(int channel_id, proto::ReadyState new_state) {
@@ -250,7 +257,8 @@ SocketEvent Logger::CreateEvent(EventType event_type) {
   return event;
 }
 
-void Logger::LogSocketEvent(int channel_id, const SocketEvent& socket_event) {
+AggregatedSocketEvent& Logger::LogSocketEvent(int channel_id,
+                                              const SocketEvent& socket_event) {
   AggregatedSocketEventLogMap::iterator it =
       aggregated_socket_events_.find(channel_id);
   if (it == aggregated_socket_events_.end()) {
@@ -258,8 +266,11 @@ void Logger::LogSocketEvent(int channel_id, const SocketEvent& socket_event) {
       AggregatedSocketEventLogMap::iterator erase_it =
           aggregated_socket_events_.begin();
 
-      num_evicted_aggregated_socket_events_++;
-      num_evicted_socket_events_ += erase_it->second->socket_events.size();
+      log_.set_num_evicted_aggregated_socket_events(
+          log_.num_evicted_aggregated_socket_events() + 1);
+      log_.set_num_evicted_socket_events(
+          log_.num_evicted_socket_events() +
+          erase_it->second->socket_events.size());
 
       aggregated_socket_events_.erase(erase_it);
     }
@@ -274,7 +285,7 @@ void Logger::LogSocketEvent(int channel_id, const SocketEvent& socket_event) {
   std::deque<proto::SocketEvent>& socket_events = it->second->socket_events;
   if (socket_events.size() >= kMaxEventsPerSocket) {
     socket_events.pop_front();
-    num_evicted_socket_events_++;
+    log_.set_num_evicted_socket_events(log_.num_evicted_socket_events() + 1);
   }
 
   socket_events.push_back(socket_event);
@@ -289,15 +300,17 @@ void Logger::LogSocketEvent(int channel_id, const SocketEvent& socket_event) {
   }
   if (socket_event.has_nss_error_code())
     it->second->last_errors.nss_error_code = socket_event.nss_error_code();
+
+  return it->second->aggregated_socket_event;
 }
 
 scoped_ptr<char[]> Logger::GetLogs(size_t* length) const {
   *length = 0;
 
   Log log;
-  log.set_num_evicted_aggregated_socket_events(
-      num_evicted_aggregated_socket_events_);
-  log.set_num_evicted_socket_events(num_evicted_socket_events_);
+  // Copy "global" values from |log_|. Don't use |log_| directly since this
+  // function is const.
+  log.CopyFrom(log_);
 
   for (AggregatedSocketEventLogMap::const_iterator it =
            aggregated_socket_events_.begin();
@@ -329,8 +342,7 @@ scoped_ptr<char[]> Logger::GetLogs(size_t* length) const {
 
 void Logger::Reset() {
   aggregated_socket_events_.clear();
-  num_evicted_aggregated_socket_events_ = 0;
-  num_evicted_socket_events_ = 0;
+  log_.Clear();
 }
 
 LastErrors Logger::GetLastErrors(int channel_id) const {

extensions/browser/api/cast_channel/logger.h

@@ -117,18 +117,17 @@ class Logger : public base::RefCounted<Logger> {
   // Records |event| associated with |channel_id|.
   // If the internal map is already logging maximum number of sockets and this
   // is a new socket, the socket with the smallest channel id will be discarded.
-  // Returns a pointer to the Event proto with |event_type| and
-  // timestamp populated.
-  void LogSocketEvent(int channel_id, const proto::SocketEvent& socket_event);
+  // Returns a reference to the AggregatedSocketEvent proto created/modified.
+  proto::AggregatedSocketEvent& LogSocketEvent(
+      int channel_id,
+      const proto::SocketEvent& socket_event);
 
   scoped_ptr<base::TickClock> clock_;
   AggregatedSocketEventLogMap aggregated_socket_events_;
   base::TimeTicks unix_epoch_time_ticks_;
 
-  // Number of socket / event entries evicted by the logger due to size
-  // constraints.
-  int num_evicted_aggregated_socket_events_;
-  int num_evicted_socket_events_;
+  // Log proto holding global statistics.
+  proto::Log log_;
 
   base::ThreadChecker thread_checker_;
 

extensions/browser/api/cast_channel/logger_unittest.cc

@@ -182,6 +182,45 @@ TEST_F(CastChannelLoggerTest, BasicLogging) {
   }
 }
 
+TEST_F(CastChannelLoggerTest, LogSocketReadWrite) {
+  logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, 50);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+  logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, 30);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+  logger_->LogSocketEventWithRv(1, EventType::SOCKET_READ, -1);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+  logger_->LogSocketEventWithRv(1, EventType::SOCKET_WRITE, 20);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+
+  logger_->LogSocketEventWithRv(2, EventType::SOCKET_READ, 100);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+  logger_->LogSocketEventWithRv(2, EventType::SOCKET_WRITE, 100);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+  logger_->LogSocketEventWithRv(2, EventType::SOCKET_WRITE, -5);
+  clock_->Advance(base::TimeDelta::FromMicroseconds(1));
+
+  scoped_ptr<Log> log = GetLog();
+  ASSERT_TRUE(log.get() != NULL);
+
+  ASSERT_EQ(2, log->aggregated_socket_event_size());
+  {
+    const AggregatedSocketEvent& aggregated_socket_event =
+        log->aggregated_socket_event(0);
+    EXPECT_EQ(1, aggregated_socket_event.id());
+    EXPECT_EQ(4, aggregated_socket_event.socket_event_size());
+    EXPECT_EQ(80, aggregated_socket_event.bytes_read());
+    EXPECT_EQ(20, aggregated_socket_event.bytes_written());
+  }
+  {
+    const AggregatedSocketEvent& aggregated_socket_event =
+        log->aggregated_socket_event(1);
+    EXPECT_EQ(2, aggregated_socket_event.id());
+    EXPECT_EQ(3, aggregated_socket_event.socket_event_size());
+    EXPECT_EQ(100, aggregated_socket_event.bytes_read());
+    EXPECT_EQ(100, aggregated_socket_event.bytes_written());
+  }
+}
+
 TEST_F(CastChannelLoggerTest, TooManySockets) {
   for (int i = 0; i < kMaxSocketsToLog + 5; i++) {
     logger_->LogSocketEvent(i, EventType::CAST_SOCKET_CREATED);

extensions/browser/api/cast_channel/logging.proto

@@ -133,6 +133,8 @@ message AggregatedSocketEvent {
   optional int32 endpoint_id = 2;
   optional ChannelAuth channel_auth_type = 3;
   repeated SocketEvent socket_event = 4;
+  optional int64 bytes_read = 5;
+  optional int64 bytes_written = 6;
 }
 
 message Log {
@@ -144,6 +146,4 @@ message Log {
 
   // Number of event log entries evicted by the logger due to size constraints.
   optional int32 num_evicted_socket_events = 3;
-
-  // TODO(imcheng): Add other stats, such as bytes read/written across sockets.
 }