Cast:Updating logging

media/cast/logging/logging_impl.cc

Index: media/cast/logging/logging_impl.cc
diff --git a/media/cast/logging/logging_impl.cc b/media/cast/logging/logging_impl.cc
index 1c67c50e80fe705851d9a886de655bdf0151dde0..1da4bba50950c53e14bbd908249b32047601886a 100644
--- a/media/cast/logging/logging_impl.cc
+++ b/media/cast/logging/logging_impl.cc
@@ -24,8 +24,10 @@ void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event,
                                    uint32 rtp_timestamp,
                                    uint32 frame_id) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
-  if (config_.enable_data_collection) {
+  if (config_.enable_raw_data_collection) {
     raw_.InsertFrameEvent(time_of_event, event, rtp_timestamp, frame_id);
+  }
+  if (config_.enable_stats_data_collection) {
     stats_.InsertFrameEvent(time_of_event, event, rtp_timestamp, frame_id);
   }
   if (config_.enable_tracing) {
@@ -42,15 +44,22 @@ void LoggingImpl::InsertFrameEventWithSize(const base::TimeTicks& time_of_event,
                                            uint32 frame_id,
                                            int frame_size) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
-  if (config_.enable_data_collection) {
+  if (config_.enable_raw_data_collection) {
     raw_.InsertFrameEventWithSize(time_of_event, event, rtp_timestamp, frame_id,
                                   frame_size);
+  }
+  if (config_.enable_stats_data_collection) {
     stats_.InsertFrameEventWithSize(time_of_event, event, rtp_timestamp,
                                     frame_id, frame_size);
   }
   if (config_.enable_uma_stats) {
-    UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), frame_size);
+    if (event == kAudioFrameEncoded)
+      UMA_HISTOGRAM_COUNTS("Cast.AudioFrameEncoded", frame_size);
+    else if (event == kVideoFrameEncoded) {
+      UMA_HISTOGRAM_COUNTS("Cast.VideoFrameEncoded", frame_size);
+    }
   }
+
   if (config_.enable_tracing) {
     std::string event_string = CastLoggingToString(event);
     TRACE_EVENT_INSTANT2(event_string.c_str(), "FES",
@@ -66,14 +75,20 @@ void LoggingImpl::InsertFrameEventWithDelay(
     uint32 frame_id,
     base::TimeDelta delay) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
-  if (config_.enable_data_collection) {
+  if (config_.enable_raw_data_collection) {
     raw_.InsertFrameEventWithDelay(time_of_event, event, rtp_timestamp,
                                    frame_id, delay);
+  }
+  if (config_.enable_stats_data_collection) {
     stats_.InsertFrameEventWithDelay(time_of_event, event, rtp_timestamp,
                                      frame_id, delay);
   }
   if (config_.enable_uma_stats) {
-    UMA_HISTOGRAM_TIMES(CastLoggingToString(event), delay);
+    if (event == kAudioPlayoutDelay)
+      UMA_HISTOGRAM_TIMES("Cast.AudioPlayoutDelay", delay);
+    else if (event == kVideoRenderDelay) {
+      UMA_HISTOGRAM_TIMES("Cast.VideoRendertDelay", delay);

[hguihot, 2014/01/13 19:51:10]

Typo.

[mikhal1, 2014/01/14 20:09:58]

Done.

+    }
   }
   if (config_.enable_tracing) {
     std::string event_string = CastLoggingToString(event);
@@ -112,9 +127,11 @@ void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event,
                                     uint16 max_packet_id,
                                     size_t size) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
-  if (config_.enable_data_collection) {
+  if (config_.enable_raw_data_collection) {
     raw_.InsertPacketEvent(time_of_event, event, rtp_timestamp, frame_id,
                            packet_id, max_packet_id, size);
+  }
+  if (config_.enable_stats_data_collection) {
     stats_.InsertPacketEvent(time_of_event, event, rtp_timestamp, frame_id,
                              packet_id, max_packet_id, size);
   }
@@ -129,12 +146,14 @@ void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event,
 void LoggingImpl::InsertGenericEvent(const base::TimeTicks& time_of_event,
                                      CastLoggingEvent event, int value) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
-  if (config_.enable_data_collection) {
+  if (config_.enable_raw_data_collection) {
     raw_.InsertGenericEvent(time_of_event, event, value);
+  }
+  if (config_.enable_stats_data_collection) {
     stats_.InsertGenericEvent(time_of_event, event, value);
   }
   if (config_.enable_uma_stats) {
-    UMA_HISTOGRAM_COUNTS(CastLoggingToString(event), value);
+    InsertGenericUmaEvent(event, value);
   }
   if (config_.enable_tracing) {
     std::string event_string = CastLoggingToString(event);
@@ -143,6 +162,26 @@ void LoggingImpl::InsertGenericEvent(const base::TimeTicks& time_of_event,
   }
 }
 
+void LoggingImpl::InsertGenericUmaEvent(CastLoggingEvent event, int value) {
+  switch(event) {
+    case kRttMs:
+      UMA_HISTOGRAM_COUNTS("Cast.Rtt", value);

[hguihot, 2014/01/13 19:51:10]

Cast.RttMs?

(Cast.JitterMs is used below)

[mikhal1, 2014/01/14 20:09:58]

Done.

+      break;
+    case kPacketLoss:
+      UMA_HISTOGRAM_COUNTS("Cast.PacketLoss", value);
+      break;
+    case kJitterMs:
+      UMA_HISTOGRAM_COUNTS("Cast.JitterMs", value);
+      break;
+    case kRembBitrate:
+      UMA_HISTOGRAM_COUNTS("Cast.RembBitrate", value);
+      break;
+    default:
+      // No-op
+      break;
+  }
+}
+
 // should just get the entire class, would be much easier.
 FrameRawMap LoggingImpl::GetFrameRawData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
@@ -169,26 +208,37 @@ const FrameStatsMap* LoggingImpl::GetFrameStatsData(
     for (it = stats->begin(); it != stats->end(); ++it) {
       // Check for an active event.
       if (it->second->framerate_fps > 0) {
-        std::string event_string = CastLoggingToString(it->first);
-        UMA_HISTOGRAM_COUNTS(event_string.append("_framerate_fps"),
+        // The default frame event implies frame rate.
+        UMA_HISTOGRAM_COUNTS(CastLoggingToString(it->first),

[hguihot, 2014/01/13 19:51:10]

This is not using a constant.

[mikhal1, 2014/01/14 20:09:58]

Done.

                              it->second->framerate_fps);
       } else {
-        // All active frame events trigger framerate computation.
+        // All active frame events trigger frame rate computation.
         continue;
       }
-      if (it->second->bitrate_kbps > 0) {
-        std::string evnt_string = CastLoggingToString(it->first);
-        UMA_HISTOGRAM_COUNTS(evnt_string.append("_bitrate_kbps"),
-                             it->second->framerate_fps);
+      // Bit rate should only be provided following encoding for either audio
+      // or video.
+      if (it->first == kVideoFrameEncoded) {
+        UMA_HISTOGRAM_COUNTS("Cast.VideoBitRateKbps",

[hguihot, 2014/01/13 19:51:10]

Bitrate? (no upper case R)

(RembBitrate does not use upper case R)

[mikhal1, 2014/01/14 20:09:58]

Done.

+            it->second->framerate_fps);
+      } else if (it->first == kAudioFrameEncoded) {
+        UMA_HISTOGRAM_COUNTS("Cast.AudioBitRateKbps",

[hguihot, 2014/01/13 19:51:10]

Bitrate?

[mikhal1, 2014/01/14 20:09:58]

Done.

+            it->second->framerate_fps);
       }
-      if (it->second->avg_delay_ms > 0) {
-        std::string event_string = CastLoggingToString(it->first);
-        UMA_HISTOGRAM_COUNTS(event_string.append("_avg_delay_ms"),
-                             it->second->avg_delay_ms);
-        UMA_HISTOGRAM_COUNTS(event_string.append("_min_delay_ms"),
-                             it->second->min_delay_ms);
-        UMA_HISTOGRAM_COUNTS(event_string.append("_max_delay_ms"),
-                             it->second->max_delay_ms);
+      // Delay events.
+      if (it->first == kAudioPlayoutDelay) {
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.AudioPlayoutDelayAvg",
+            it->second->avg_delay_ms);
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.AudioPlayoutDelayMin",
+            it->second->min_delay_ms);
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.AudioPlayoutDelayMax",
+            it->second->max_delay_ms);
+      } else if (it->first == kVideoRenderDelay) {
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.VideoPlayoutDelayAvg",
+            it->second->avg_delay_ms);
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.VideoPlayoutDelayMin",
+            it->second->min_delay_ms);
+        UMA_HISTOGRAM_COUNTS("Cast.Stats.VideoPlayoutDelayMax",
+            it->second->max_delay_ms);
       }
     }
   }
@@ -203,9 +253,23 @@ const PacketStatsMap* LoggingImpl::GetPacketStatsData(
   if (config_.enable_uma_stats) {
     PacketStatsMap::const_iterator it;
     for (it = stats->begin(); it != stats->end(); ++it) {
-      if (it->second > 0) {
-        std::string event_string = CastLoggingToString(it->first);
-        UMA_HISTOGRAM_COUNTS(event_string.append("_bitrate_kbps"), it->second);
+      switch (it->first) {

[hguihot, 2014/01/13 19:51:10]

Will these histograms make sense considering these numbers can represent some
arbitrary duration (i.e. the time between calls to Reset() and
GetPacketsStatsData() can be anything)?

[mikhal1, 2014/01/14 20:09:58]

That is up to the user. I'm assuming the user will call reset and get these
numbers every ~1S.
On 2014/01/13 19:51:10, hguihot wrote:

[hguihot, 2014/01/14 20:15:03]

I don't think we can assume that for all receivers though (making reading the
histograms more difficult, or impossible if the reader does not know the
sampling frequency). Can we convert those to packets/second (or other unit of
time) instead of just packets?

On 2014/01/14 20:09:58, mikhal1 wrote:

[mikhal1, 2014/01/22 15:59:57]

This implementation will be obsolete once my changes to the stats are submitted
(which follow our discussions). You will be added as a reviewer once I'll upload
that cl. Feel free to comment there.
On 2014/01/14 20:15:03, hguihot wrote:

+        case kPacketSentToPacer:
+          UMA_HISTOGRAM_COUNTS("Cast.Stats.PacketSentToPacer", it->second);
+          break;
+        case kPacketSentToNetwork:
+          UMA_HISTOGRAM_COUNTS("Cast.Stats.PacketSentToNetwork", it->second);
+          break;
+        case kPacketRetransmited:

[hguihot, 2014/01/13 19:51:10]

Typo (transmitted).

[mikhal1, 2014/01/14 20:09:58]

Done.

+          UMA_HISTOGRAM_COUNTS("Cast.Stats.PacketRetransmited", it->second);

[hguihot, 2014/01/13 19:51:10]

Same typo here too.

[mikhal1, 2014/01/14 20:09:58]

Done.

+          break;
+        case kDuplicatePacketReceived:
+          UMA_HISTOGRAM_COUNTS("Cast.Stats.DuplicatePacketReceived",
+                               it->second);
+          break;
+        default:
+          // No-op.
+          break;
       }
     }
   }
@@ -216,20 +280,16 @@ const GenericStatsMap* LoggingImpl::GetGenericStatsData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   // Get stats data.
   const GenericStatsMap* stats = stats_.GetGenericStatsData();
-  if (config_.enable_uma_stats) {
-    GenericStatsMap::const_iterator it;
-    for (it = stats->begin(); it != stats->end(); ++it) {
-      if (it->second > 0) {
-        UMA_HISTOGRAM_COUNTS(CastLoggingToString(it->first), it->second);
-      }
-    }
-  }
   return stats;
 }
 
-void LoggingImpl::Reset() {
+void LoggingImpl::ResetRaw() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   raw_.Reset();
+}
+
+void LoggingImpl::ResetStats() {
+  DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   stats_.Reset();
 }