Cast channel logging: log additional statistics.

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
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=290009

[imcheng, 2014-08-13 18:10:00]

PTAL. I will merge this with  https://codereview.chromium.org/456213002/ once
it's submitted.

[mark a. foltz, 2014-08-13 22:06:31]

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:128:
->second->aggregated_socket_event;
Is this lookup guaranteed to succeed?

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logging.proto (right):

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logging.proto:148: optional int64
total_bytes_read = 4;
Is this data interesting?  It will be aggregated across multiple sockets which
might map onto multiple devices and include sockets that were evicted from
aggregated_socket_event.

I would be okay leaving this out to keep things simpler; it's more interesting
to keep track on a socket by socket basis.

[imcheng, 2014-08-14 00:24:34]

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:128:
->second->aggregated_socket_event;
On 2014/08/13 22:06:31, mark a. foltz wrote:
> Is this lookup guaranteed to succeed?

Yes, because this entry was just added in LogSocketEvent. I added a CHECK here.

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logging.proto (right):

https://codereview.chromium.org/475463002/diff/20001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logging.proto:148: optional int64
total_bytes_read = 4;
On 2014/08/13 22:06:31, mark a. foltz wrote:
> Is this data interesting?  It will be aggregated across multiple sockets which
> might map onto multiple devices and include sockets that were evicted from
> aggregated_socket_event.
> 

Yes, this was the intention.

> I would be okay leaving this out to keep things simpler; it's more interesting
> to keep track on a socket by socket basis.

Okay. I can remove this for now.

[mark a. foltz, 2014-08-14 05:57:35]

Lgtm

Could LogSocketEvent just return the aggregated event struct that was logged to
instead of requiring a separate lookup?

[Wez, 2014-08-14 18:44:35]

lgtm

https://codereview.chromium.org/475463002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/475463002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:263: log.CopyFrom(log_);
nit: This is just to get the evicted counts? Consider adding a comment to
clarify that this is just to copy across the "global" values.

[imcheng, 2014-08-14 22:43:19]

https://codereview.chromium.org/475463002/diff/60001/extensions/browser/api/c...
File extensions/browser/api/cast_channel/logger.cc (right):

https://codereview.chromium.org/475463002/diff/60001/extensions/browser/api/c...
extensions/browser/api/cast_channel/logger.cc:263: log.CopyFrom(log_);
On 2014/08/14 18:44:35, Wez wrote:
> nit: This is just to get the evicted counts? Consider adding a comment to
> clarify that this is just to copy across the "global" values.

Done.

[imcheng, 2014-08-15 04:26:12]

On 2014/08/14 05:57:35, mark a. foltz wrote:
> Lgtm
> 
> Could LogSocketEvent just return the aggregated event struct that was logged
to
> instead of requiring a separate lookup?

Done.

[imcheng, 2014-08-15 04:26:17]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-15 04:31:04]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/475463002/120001

[imcheng, 2014-08-15 04:41:19]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-15 04:44:31]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/475463002/140001

[commit-bot: I haz the power, 2014-08-15 07:37:22]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  win_chromium_x64_rel on tryserver.chromium.win
(http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_x64_...)

[commit-bot: I haz the power, 2014-08-15 16:29:12]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-08-15 16:29:13]

Failed to apply patch for extensions/browser/api/cast_channel/logger.cc:
While running patch -p1 --forward --force --no-backup-if-mismatch;
  patching file extensions/browser/api/cast_channel/logger.cc
  Hunk #1 succeeded at 108 (offset 41 lines).
  Hunk #2 succeeded at 124 (offset 41 lines).
  Hunk #3 succeeded at 161 (offset 41 lines).
  Hunk #4 succeeded at 257 (offset 41 lines).
  Hunk #5 succeeded at 266 (offset 41 lines).
  Hunk #6 succeeded at 285 (offset 41 lines).
  Hunk #7 FAILED at 259.
  Hunk #8 succeeded at 340 (offset 47 lines).
  1 out of 8 hunks FAILED -- saving rejects to file
extensions/browser/api/cast_channel/logger.cc.rej

Patch:       extensions/browser/api/cast_channel/logger.cc
Index: extensions/browser/api/cast_channel/logger.cc
diff --git a/extensions/browser/api/cast_channel/logger.cc
b/extensions/browser/api/cast_channel/logger.cc
index
3d08c0ab4e86c51a5c92fb60a914be2acd2ff61e..47341e4226dbaf919f33b4f95963419a396c483d
100644
--- a/extensions/browser/api/cast_channel/logger.cc
+++ b/extensions/browser/api/cast_channel/logger.cc
@@ -67,10 +67,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
@@ -86,11 +83,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() ==
@@ -125,7 +120,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) {
@@ -209,7 +216,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()) {
@@ -217,8 +225,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);
     }
@@ -233,7 +244,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);
@@ -248,15 +259,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;
 }
 
 bool Logger::LogToString(std::string* output) const {
   output->clear();
 
   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();
@@ -282,8 +295,7 @@ bool Logger::LogToString(std::string* output) 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 {

[imcheng, 2014-08-15 17:07:53]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-15 17:09:57]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/475463002/160001

[imcheng, 2014-08-15 17:17:25]

The CQ bit was checked by imcheng@chromium.org

[commit-bot: I haz the power, 2014-08-15 17:19:42]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/imcheng@chromium.org/475463002/180001

[commit-bot: I haz the power, 2014-08-15 19:57:03]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  android_dbg_triggered_tests on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/android_dbg_tri...)

[commit-bot: I haz the power, 2014-08-15 21:18:11]

Committed patchset #7 (180001) as 290009