Cast:Updating logging

media/cast/logging/logging_impl.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/debug/trace_event.h"
 #include "base/metrics/histogram.h"
 #include "media/cast/logging/logging_impl.h"
 #include "net/base/big_endian.h"
 
 namespace media {
 namespace cast {
 
 LoggingImpl::LoggingImpl(scoped_refptr<base::TaskRunner> main_thread_proxy,
                          const CastLoggingConfig& config)
     : main_thread_proxy_(main_thread_proxy),
       config_(config),
       raw_(),
       stats_() {}
 
 LoggingImpl::~LoggingImpl() {}
 
 void LoggingImpl::InsertFrameEvent(const base::TimeTicks& time_of_event,
                                    CastLoggingEvent 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) {
     std::string event_string = CastLoggingToString(event);
     TRACE_EVENT_INSTANT2(event_string.c_str(), "FE",
         TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "frame_id",
         frame_id);
   }
 }
 
 void LoggingImpl::InsertFrameEventWithSize(const base::TimeTicks& time_of_event,
                                            CastLoggingEvent event,
                                            uint32 rtp_timestamp,
                                            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",
         TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "frame_size",
         frame_size);
   }
 }
 
 void LoggingImpl::InsertFrameEventWithDelay(
     const base::TimeTicks& time_of_event,
     CastLoggingEvent event,
     uint32 rtp_timestamp,
     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);
     TRACE_EVENT_INSTANT2(event_string.c_str(), "FED",
         TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp, "delay",
         delay.InMilliseconds());
   }
 }
 
 void LoggingImpl::InsertPacketListEvent(const base::TimeTicks& time_of_event,
@@ skipping 18 matching lines @@
 }
 
 void LoggingImpl::InsertPacketEvent(const base::TimeTicks& time_of_event,
                                     CastLoggingEvent event,
                                     uint32 rtp_timestamp,
                                     uint32 frame_id,
                                     uint16 packet_id,
                                     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);
   }
   if (config_.enable_tracing) {
     std::string event_string = CastLoggingToString(event);
     TRACE_EVENT_INSTANT2(event_string.c_str(), "PE",
         TRACE_EVENT_SCOPE_THREAD, "rtp_timestamp", rtp_timestamp,
         "packet_id", packet_id);
   }
 }
 
 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);
     TRACE_EVENT_INSTANT1(event_string.c_str(), "GE",
         TRACE_EVENT_SCOPE_THREAD, "value", value);
   }
 }
 
+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());
   return raw_.GetFrameData();
 }
 
 PacketRawMap LoggingImpl::GetPacketRawData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   return raw_.GetPacketData();
 }
 
 GenericRawMap LoggingImpl::GetGenericRawData() {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   return raw_.GetGenericData();
 }
 
 const FrameStatsMap* LoggingImpl::GetFrameStatsData(
     const base::TimeTicks& now) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   // Get stats data.
   const FrameStatsMap* stats = stats_.GetFrameStatsData(now);
   if (config_.enable_uma_stats) {
     FrameStatsMap::const_iterator it;
     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);
       }
     }
   }
   return stats;
 }
 
 const PacketStatsMap* LoggingImpl::GetPacketStatsData(
     const base::TimeTicks& now) {
   DCHECK(main_thread_proxy_->RunsTasksOnCurrentThread());
   // Get stats data.
   const PacketStatsMap* stats = stats_.GetPacketStatsData(now);
   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;
       }
     }
   }
   return stats;
 }
 
 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();
 }
 
 }  // namespace cast
 }  // namespace media