Cast: Provide more meaningful stats.

media/cast/logging/stats_event_subscriber.cc

 // Copyright 2014 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 "media/cast/logging/stats_event_subscriber.h"
 
 #include "base/logging.h"
+#include "base/values.h"
+
+#define STAT_ENUM_TO_STRING(enum) \
+  case enum:                      \
+    return #enum
 
 namespace media {
 namespace cast {
 
-StatsEventSubscriber::StatsEventSubscriber(EventMediaType event_media_type)
-    : event_media_type_(event_media_type) {}
+namespace {
+
+using media::cast::CastLoggingEvent;
+using media::cast::EventMediaType;
+
+const size_t kMaxFrameEventTimeMapSize = 100;
+const size_t kMaxPacketEventTimeMapSize = 1000;
+
+CastLoggingEvent GetCapturedEvent(EventMediaType media_type) {

[hubbe, 2014/04/15 00:23:22]

Ouch, this level of repetition hurts my brain.

[imcheng, 2014/04/15 01:18:36]

I can't think of much that can be done here. This is because we split events
types into audio/video, and this class needs to work for either audio or video.
The duplication has to happen somewhere. I tried to make these functions take up
less space.

[miu, 2014/04/15 21:29:43]

Suggestion (you probably want to put this in the header file where the enums are
declared):

#define CAST_LOGGING_EVENT(which, media_type)  \
  ((media_type) == AUDIO_EVENT ? kAudio##which : kVideo##which)

Usage example (lines 115-120 become):

  if (type == CAST_LOGGING_EVENT(FrameCaptured, event_media_type_)) {
    it->second.min_delay = frame_event.delay_delta;
    RecordFrameCapturedTime(frame_event);
  } else if (type == CAST_LOGGING_EVENT(PlayoutDelay, event_media_type_)) {
    RecordE2ELatency(frame_event);
  }

[imcheng, 2014/04/17 19:19:06]

Honestly I am not a huge fan of macros in a situation like this. It makes the
code harder to read and search. It also places restriction on event type
namings. (e.g. there are events called kDuplicate{Audio,Video}PacketReceived
which the macro won't work for, but putting the {Audio,Video} in the front
sounds strange). 

I did turn these functions into a one-liner using ternary operator though. We
can move these helper functions into logging_defines.{cc,h} if needed.


On 2014/04/15 21:29:43, miu wrote:

[miu, 2014/04/18 00:02:03]

Thinking about this some more, the real problem is that the CastLoggingEvent
enum shouldn't define the same events for audio and video.  There should be one
set of events, and then the stream ID used to differentiate between the logging
for the audio or video stream.

Oh well.  Leave it this way for now if you want, and hopefully we can get rid of
this when logging is per-stream rather than just the two-stream audio/video bool
paradigm.

[imcheng, 2014/04/18 18:20:27]

Yes, it is unfortunate that we have split event types, which sort of led to this
situation. It is already baked into RTCP so it is used by receiver
implementations as well. Changing this will not be easy, we will probably have
to define new event types and deprecate existing ones.

On 2014/04/18 00:02:03, miu wrote:

+  if (media_type == AUDIO_EVENT)
+    return kAudioFrameCaptured;
+  else
+    return kVideoFrameCaptured;
+}
+
+CastLoggingEvent GetEncodedEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioFrameEncoded;
+  else
+    return kVideoFrameEncoded;
+}
+
+CastLoggingEvent GetDecodedEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioFrameDecoded;
+  else
+    return kVideoFrameDecoded;
+}
+
+CastLoggingEvent GetPlayoutEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioPlayoutDelay;
+  else
+    return kVideoRenderDelay;
+}
+
+CastLoggingEvent GetPacketSentEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioPacketSentToNetwork;
+  else
+    return kVideoPacketSentToNetwork;
+}
+
+CastLoggingEvent GetPacketReceivedEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioPacketReceived;
+  else
+    return kVideoPacketReceived;
+}
+
+CastLoggingEvent GetPacketRetransmittedEvent(EventMediaType media_type) {
+  if (media_type == AUDIO_EVENT)
+    return kAudioPacketRetransmitted;
+  else
+    return kVideoPacketRetransmitted;
+}
+
+}  // namespace
+
+StatsEventSubscriber::StatsEventSubscriber(
+    EventMediaType event_media_type,
+    base::TickClock* clock,
+    ReceiverTimeOffsetEstimator* offset_estimator)
+    : event_media_type_(event_media_type),
+      total_network_latency_ms_(0),
+      network_latency_datapoints_(0),
+      total_e2e_latency_ms_(0),
+      e2e_latency_datapoints_(0),
+      start_time_(clock->NowTicks()),
+      clock_(clock),
+      offset_estimator_(offset_estimator) {
+  DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
+}
 
 StatsEventSubscriber::~StatsEventSubscriber() {
   DCHECK(thread_checker_.CalledOnValidThread());
 }
 
 void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   CastLoggingEvent type = frame_event.type;
   if (GetEventMediaType(type) != event_media_type_)
     return;
 
   FrameStatsMap::iterator it = frame_stats_.find(type);
   if (it == frame_stats_.end()) {
     FrameLogStats stats;
-    stats.first_event_time = frame_event.timestamp;
-    stats.last_event_time = frame_event.timestamp;
     stats.event_counter = 1;
     stats.sum_size = frame_event.size;
-    stats.min_delay = frame_event.delay_delta;
-    stats.max_delay = frame_event.delay_delta;
     stats.sum_delay = frame_event.delay_delta;
     frame_stats_.insert(std::make_pair(type, stats));
   } else {
     ++(it->second.event_counter);
-    it->second.last_event_time = frame_event.timestamp;
     it->second.sum_size += frame_event.size;
     it->second.sum_delay += frame_event.delay_delta;
-    if (frame_event.delay_delta > it->second.max_delay)
-      it->second.max_delay = frame_event.delay_delta;
-    if (frame_event.delay_delta < it->second.min_delay)
-      it->second.min_delay = frame_event.delay_delta;
+  }
+
+  if (type == GetCapturedEvent(event_media_type_)) {
+    RecordFrameCapturedTime(frame_event);
+  } else if (type == GetPlayoutEvent(event_media_type_)) {
+    RecordE2ELatency(frame_event);
   }
 }
 
 void StatsEventSubscriber::OnReceivePacketEvent(
     const PacketEvent& packet_event) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   CastLoggingEvent type = packet_event.type;
   if (GetEventMediaType(type) != event_media_type_)
     return;
 
   PacketStatsMap::iterator it = packet_stats_.find(type);
   if (it == packet_stats_.end()) {
     PacketLogStats stats;
-    stats.first_event_time = packet_event.timestamp;
-    stats.last_event_time = packet_event.timestamp;
     stats.event_counter = 1;
     stats.sum_size = packet_event.size;
     packet_stats_.insert(std::make_pair(type, stats));
   } else {
-    it->second.last_event_time = packet_event.timestamp;
     ++(it->second.event_counter);
     it->second.sum_size += packet_event.size;
   }
+
+  if (type == GetPacketSentEvent(event_media_type_)) {
+    RecordPacketSentTime(packet_event);
+  } else if (type == GetPacketRetransmittedEvent(event_media_type_)) {
+    // We only measure network latency using packets that doesn't have to be
+    // retransmitted as there is precisely one sent-receive timestamp pairs.
+    ErasePacketSentTime(packet_event);
+  } else if (type == GetPacketReceivedEvent(event_media_type_)) {
+    RecordNetworkLatency(packet_event);
+  }
 }
 
 void StatsEventSubscriber::OnReceiveGenericEvent(
     const GenericEvent& generic_event) {
   DCHECK(thread_checker_.CalledOnValidThread());
-
-  CastLoggingEvent type = generic_event.type;
-  if (GetEventMediaType(type) != event_media_type_)
-    return;
-
-  GenericStatsMap::iterator it = generic_stats_.find(type);
-  if (it == generic_stats_.end()) {
-    GenericLogStats stats;
-    stats.first_event_time = generic_event.timestamp;
-    stats.last_event_time = generic_event.timestamp;
-    stats.event_counter = 1;
-    stats.sum = generic_event.value;
-    stats.sum_squared = generic_event.value * generic_event.value;
-    stats.min = generic_event.value;
-    stats.max = generic_event.value;
-    generic_stats_.insert(std::make_pair(type, stats));
-  } else {
-    it->second.last_event_time = generic_event.timestamp;
-    ++(it->second.event_counter);
-    it->second.sum += generic_event.value;
-    it->second.sum_squared += generic_event.value * generic_event.value;
-    if (it->second.min > generic_event.value) {
-      it->second.min = generic_event.value;
-    } else if (it->second.max < generic_event.value) {
-      it->second.max = generic_event.value;
-    }
-  }
-}
-
-void StatsEventSubscriber::GetFrameStats(FrameStatsMap* frame_stats_map) const {
-  DCHECK(thread_checker_.CalledOnValidThread());
-  DCHECK(frame_stats_map);
-
-  frame_stats_map->clear();
-  frame_stats_map->insert(frame_stats_.begin(), frame_stats_.end());
-}
-
-void StatsEventSubscriber::GetPacketStats(
-    PacketStatsMap* packet_stats_map) const {
-  DCHECK(thread_checker_.CalledOnValidThread());
-  DCHECK(packet_stats_map);
-
-  packet_stats_map->clear();
-  packet_stats_map->insert(packet_stats_.begin(), packet_stats_.end());
-}
-
-void StatsEventSubscriber::GetGenericStats(
-    GenericStatsMap* generic_stats_map) const {
-  DCHECK(thread_checker_.CalledOnValidThread());
-  DCHECK(generic_stats_map);
-
-  generic_stats_map->clear();
-  generic_stats_map->insert(generic_stats_.begin(), generic_stats_.end());
+  // Not interested in generic events.
+}
+
+scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
+  StatsMap stats_map;
+  GetStatsInternal(&stats_map);
+  scoped_ptr<base::DictionaryValue> ret(new base::DictionaryValue);
+
+  scoped_ptr<base::DictionaryValue> stats(new base::DictionaryValue);
+  for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
+       ++it) {
+    stats->SetDouble(CastStatToString(it->first), it->second);
+  }
+
+  ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
+           stats.release());
+
+  return ret.Pass();
 }
 
 void StatsEventSubscriber::Reset() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   frame_stats_.clear();
   packet_stats_.clear();
-  generic_stats_.clear();
-}
+  total_network_latency_ms_ = 0;
+  network_latency_datapoints_ = 0;
+  total_e2e_latency_ms_ = 0;
+  e2e_latency_datapoints_ = 0;
+  frame_captured_times_.clear();
+  packet_sent_times_.clear();
+  start_time_ = clock_->NowTicks();
+}
+
+// static
+const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
+  switch (stat) {
+    STAT_ENUM_TO_STRING(CAPTURE_FPS);
+    STAT_ENUM_TO_STRING(ENCODE_FPS);
+    STAT_ENUM_TO_STRING(DECODE_FPS);
+    STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
+    STAT_ENUM_TO_STRING(AVG_PLAYOUT_DELAY_MS);
+    STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
+    STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
+    STAT_ENUM_TO_STRING(ENCODE_KBPS);
+    STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
+    STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
+    STAT_ENUM_TO_STRING(PACKET_LOSS_PERCENTAGE);
+  }
+  NOTREACHED();
+  return "";
+}
+
+void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
+  DCHECK(thread_checker_.CalledOnValidThread());
+
+  stats_map->clear();
+
+  base::TimeTicks end_time = clock_->NowTicks();
+
+  PopulateFpsStat(
+      end_time, GetCapturedEvent(event_media_type_), CAPTURE_FPS, stats_map);
+  PopulateFpsStat(
+      end_time, GetEncodedEvent(event_media_type_), ENCODE_FPS, stats_map);
+  PopulateFpsStat(
+      end_time, GetDecodedEvent(event_media_type_), DECODE_FPS, stats_map);
+  PopulatePlayoutDelayStat(stats_map);
+  PopulateFrameBitrateStat(end_time, stats_map);
+  PopulatePacketBitrateStat(end_time,
+                            GetPacketSentEvent(event_media_type_),
+                            TRANSMISSION_KBPS,
+                            stats_map);
+  PopulatePacketBitrateStat(end_time,
+                            GetPacketRetransmittedEvent(event_media_type_),
+                            RETRANSMISSION_KBPS,
+                            stats_map);
+  PopulatePacketLossPercentageStat(stats_map);
+
+  if (network_latency_datapoints_ > 0) {
+    double avg_network_latency_ms =
+        static_cast<double>(total_network_latency_ms_) /
+        network_latency_datapoints_;
+    stats_map->insert(
+        std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
+  }
+
+  if (e2e_latency_datapoints_ > 0) {
+    double avg_e2e_latency_ms =
+        static_cast<double>(total_e2e_latency_ms_) / e2e_latency_datapoints_;
+    stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
+  }
+}
+
+bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
+  base::TimeDelta receiver_offset_lower_bound;
+  base::TimeDelta receiver_offset_upper_bound;
+  if (!offset_estimator_->GetReceiverOffsetBounds(
+          &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
+    return false;
+  }
+
+  *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
+  return true;
+}
+
+void StatsEventSubscriber::RecordFrameCapturedTime(
+    const FrameEvent& frame_event) {
+  frame_captured_times_.insert(
+      std::make_pair(frame_event.rtp_timestamp, frame_event.timestamp));
+  if (frame_captured_times_.size() > kMaxFrameEventTimeMapSize)
+    frame_captured_times_.erase(frame_captured_times_.begin());
+}
+
+void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
+  base::TimeDelta receiver_offset;
+  if (!GetReceiverOffset(&receiver_offset))
+    return;
+
+  FrameEventTimeMap::iterator it =
+      frame_captured_times_.find(frame_event.rtp_timestamp);
+  if (it == frame_captured_times_.end())
+    return;
+
+  // Playout time is event time + playout delay.
+  base::TimeTicks playout_time =
+      frame_event.timestamp + frame_event.delay_delta - receiver_offset;
+  int64 e2e_latency_ms = (playout_time - it->second).InMilliseconds();
+
+  // Bogus value - probably because the offset value has not stabilized enough
+  // yet.
+  if (e2e_latency_ms <= 0)
+    return;
+
+  total_e2e_latency_ms_ += e2e_latency_ms;
+  e2e_latency_datapoints_++;
+}
+
+void StatsEventSubscriber::RecordPacketSentTime(
+    const PacketEvent& packet_event) {
+  std::pair<RtpTimestamp, uint16> key(
+      std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+  packet_sent_times_.insert(std::make_pair(key, packet_event.timestamp));
+  if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
+    packet_sent_times_.erase(packet_sent_times_.begin());
+}
+
+void StatsEventSubscriber::ErasePacketSentTime(
+    const PacketEvent& packet_event) {
+  std::pair<RtpTimestamp, uint16> key(
+      std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+  packet_sent_times_.erase(key);
+}
+
+void StatsEventSubscriber::RecordNetworkLatency(
+    const PacketEvent& packet_event) {
+  base::TimeDelta receiver_offset;
+  if (!GetReceiverOffset(&receiver_offset))
+    return;
+
+  base::TimeTicks packet_sent_time;
+  std::pair<RtpTimestamp, uint16> key(
+      std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
+  PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
+  if (it == packet_sent_times_.end())
+    return;
+  packet_sent_time = it->second;
+
+  // Subtract by offset.
+  base::TimeTicks packet_received_time =
+      packet_event.timestamp - receiver_offset;
+
+  int64 latency_ms = (packet_received_time - packet_sent_time).InMilliseconds();
+
+  // Bogus value - probably because the offset value has not stabilized enough
+  // yet.
+  if (latency_ms <= 0)
+    return;
+
+  total_network_latency_ms_ += latency_ms;
+  network_latency_datapoints_++;
+}
+
+void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
+                                           CastLoggingEvent event,
+                                           CastStat stat,
+                                           StatsMap* stats_map) const {
+  FrameStatsMap::const_iterator it = frame_stats_.find(event);
+  if (it != frame_stats_.end()) {
+    double fps = 0.0;
+    int64 duration_ms = (end_time - start_time_).InMilliseconds();
+    int count = it->second.event_counter;
+    if (duration_ms != 0 && count != 0)
+      fps = static_cast<double>(count) / duration_ms * 1000;
+    stats_map->insert(std::make_pair(stat, fps));
+  }
+}
+
+void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
+  CastLoggingEvent event = GetPlayoutEvent(event_media_type_);
+  FrameStatsMap::const_iterator it = frame_stats_.find(event);
+  if (it != frame_stats_.end()) {
+    double avg_delay_ms = 0.0;
+    int64 sum_delay_ms = it->second.sum_delay.InMilliseconds();
+    int count = it->second.event_counter;
+    if (sum_delay_ms != 0 && count != 0)
+      avg_delay_ms = static_cast<double>(sum_delay_ms) / count;
+    stats_map->insert(std::make_pair(AVG_PLAYOUT_DELAY_MS, avg_delay_ms));
+  }
+}
+
+void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
+                                                    StatsMap* stats_map) const {
+  CastLoggingEvent event = GetEncodedEvent(event_media_type_);
+  FrameStatsMap::const_iterator it = frame_stats_.find(event);
+  if (it != frame_stats_.end()) {
+    double kbps = 0;
+    int64 duration_ms = (end_time - start_time_).InMilliseconds();
+    if (it->second.sum_size != 0 && duration_ms != 0) {
+      kbps = static_cast<double>(it->second.sum_size) / duration_ms * 8;
+    }
+
+    stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
+  }
+}
+
+void StatsEventSubscriber::PopulatePacketBitrateStat(
+    base::TimeTicks end_time,
+    CastLoggingEvent event,
+    CastStat stat,
+    StatsMap* stats_map) const {
+  PacketStatsMap::const_iterator it = packet_stats_.find(event);
+  if (it != packet_stats_.end()) {
+    double kbps = 0;
+    int64 duration_ms = (end_time - start_time_).InMilliseconds();
+    if (it->second.sum_size != 0 && duration_ms != 0) {
+      kbps = static_cast<double>(it->second.sum_size) / duration_ms * 8;
+    }
+
+    stats_map->insert(std::make_pair(stat, kbps));
+  }
+}
+
+void StatsEventSubscriber::PopulatePacketLossPercentageStat(
+    StatsMap* stats_map) const {
+  // We assume that retransmission means that the packet's previous
+  // (re)transmission was lost.
+  // This means the percentage of packet loss is
+  // (# of retransmit events) / (# of transmit + retransmit events).
+  CastLoggingEvent packet_sent_event = GetPacketSentEvent(event_media_type_);
+  CastLoggingEvent packet_retransmitted_event =
+      GetPacketRetransmittedEvent(event_media_type_);
+  PacketStatsMap::const_iterator sent_it =
+      packet_stats_.find(packet_sent_event);
+  if (sent_it == packet_stats_.end())
+    return;
+  PacketStatsMap::const_iterator retransmitted_it =
+      packet_stats_.find(packet_retransmitted_event);
+  int sent_count = sent_it->second.event_counter;
+  int retransmitted_count = 0;
+  if (retransmitted_it != packet_stats_.end())
+    retransmitted_count = retransmitted_it->second.event_counter;
+  double packet_loss_percentage = static_cast<double>(retransmitted_count) /
+                                  (sent_count + retransmitted_count) * 100;
+  stats_map->insert(
+      std::make_pair(PACKET_LOSS_PERCENTAGE, packet_loss_percentage));
+}
+
+StatsEventSubscriber::FrameLogStats::FrameLogStats()
+    : event_counter(0), sum_size(0) {}
+StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
+
+StatsEventSubscriber::PacketLogStats::PacketLogStats()
+    : event_counter(0), sum_size(0) {}
+StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
 
 }  // namespace cast
 }  // namespace media