Cast: Provide more meaningful stats.

media/cast/logging/stats_event_subscriber.cc

Index: media/cast/logging/stats_event_subscriber.cc
diff --git a/media/cast/logging/stats_event_subscriber.cc b/media/cast/logging/stats_event_subscriber.cc
index 9a2df9d9ef8bb5df17d8d19db9af4be05397dab3..212fa43ee6f306192b8ed6439089eca1bb21a882 100644
--- a/media/cast/logging/stats_event_subscriber.cc
+++ b/media/cast/logging/stats_event_subscriber.cc
@@ -5,12 +5,75 @@
 #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/24 22:53:54]

I'll be happy when we can get rid of these. :)

[imcheng, 2014/04/25 15:35:44]

ACK.

+  return media_type == AUDIO_EVENT ? kAudioFrameCaptured : kVideoFrameCaptured;
+}
+
+CastLoggingEvent GetEncodedEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioFrameEncoded : kVideoFrameEncoded;
+}
+
+CastLoggingEvent GetDecodedEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioFrameDecoded : kVideoFrameDecoded;
+}
+
+CastLoggingEvent GetPlayoutEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioPlayoutDelay : kVideoRenderDelay;
+}
+
+CastLoggingEvent GetPacketSentEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioPacketSentToNetwork :
+                                     kVideoPacketSentToNetwork;
+}
+
+CastLoggingEvent GetPacketReceivedEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioPacketReceived :
+                                     kVideoPacketReceived;
+}
+
+CastLoggingEvent GetPacketRetransmittedEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioPacketRetransmitted :
+                                     kVideoPacketRetransmitted;
+}
+
+CastLoggingEvent GetRtcpPacketReceivedEvent(EventMediaType media_type) {
+  return media_type == AUDIO_EVENT ? kAudioRtcpPacketReceived :
+                                     kVideoRtcpPacketReceived;
+}
+
+}  // namespace
+
+StatsEventSubscriber::StatsEventSubscriber(
+    EventMediaType event_media_type,
+    base::TickClock* clock,
+    ReceiverTimeOffsetEstimator* offset_estimator)
+    : event_media_type_(event_media_type),
+      clock_(clock),
+      offset_estimator_(offset_estimator),
+      network_latency_datapoints_(0),
+      e2e_latency_datapoints_(0) {
+  DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
+  base::TimeTicks now = clock_->NowTicks();
+  start_time_ = now;
+  last_response_received_time_ = now;
+}
 
 StatsEventSubscriber::~StatsEventSubscriber() {
   DCHECK(thread_checker_.CalledOnValidThread());
@@ -26,23 +89,20 @@ void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
   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);
   }
 }
 
@@ -57,16 +117,23 @@ void StatsEventSubscriber::OnReceivePacketEvent(
   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(
@@ -77,63 +144,271 @@ void StatsEventSubscriber::OnReceiveGenericEvent(
   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;
-    }
+  if (type == GetRtcpPacketReceivedEvent(event_media_type_))
+    last_response_received_time_ = generic_event.timestamp;
+}
+
+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::GetFrameStats(FrameStatsMap* frame_stats_map) const {
+void StatsEventSubscriber::Reset() {
   DCHECK(thread_checker_.CalledOnValidThread());
-  DCHECK(frame_stats_map);
 
-  frame_stats_map->clear();
-  frame_stats_map->insert(frame_stats_.begin(), frame_stats_.end());
+  frame_stats_.clear();
+  packet_stats_.clear();
+  total_network_latency_ = base::TimeDelta();
+  network_latency_datapoints_ = 0;
+  total_e2e_latency_ = base::TimeDelta();
+  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_FRACTION);
+    STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
+  }
+  NOTREACHED();
+  return "";
 }
 
-void StatsEventSubscriber::GetPacketStats(
-    PacketStatsMap* packet_stats_map) const {
+void StatsEventSubscriber::GetStatsInternal(StatsMap* 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());
+  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 =
+        total_network_latency_.InMillisecondsF() /
+        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 =
+        total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
+    stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
+  }
+
+  stats_map->insert(
+      std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
+      (end_time - last_response_received_time_).InMillisecondsF()));
 }
 
-void StatsEventSubscriber::GetGenericStats(
-    GenericStatsMap* generic_stats_map) const {
-  DCHECK(thread_checker_.CalledOnValidThread());
-  DCHECK(generic_stats_map);
+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;
+  }
 
-  generic_stats_map->clear();
-  generic_stats_map->insert(generic_stats_.begin(), generic_stats_.end());
+  *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
+  return true;
 }
 
-void StatsEventSubscriber::Reset() {
-  DCHECK(thread_checker_.CalledOnValidThread());
+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());
+}
 
-  frame_stats_.clear();
-  packet_stats_.clear();
-  generic_stats_.clear();
+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;
+  total_e2e_latency_ += playout_time - it->second;
+  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;
+
+  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;
+  base::TimeTicks packet_sent_time = it->second;
+
+  // Subtract by offset.
+  base::TimeTicks packet_received_time =
+      packet_event.timestamp - receiver_offset;
+
+  total_network_latency_ += packet_received_time - packet_sent_time;
+  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;
+    base::TimeDelta duration = (end_time - start_time_);
+    int count = it->second.event_counter;
+    if (duration > base::TimeDelta())
+      fps = count / duration.InSecondsF();
+    stats_map->insert(std::make_pair(stat, fps));

[hubbe, 2014/04/24 22:53:54]

Why not just (*stats_map)[stats] = fps; ?

[imcheng, 2014/04/25 15:35:44]

insert is supposed to be more efficient than operator[] + operator= but in this
case it doesn't really matter. I guess I am just used to using insert() all the
time.

+  }
+}
+
+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;
+    base::TimeDelta sum_delay = it->second.sum_delay;
+    int count = it->second.event_counter;
+    if (count != 0)
+      avg_delay_ms = sum_delay.InMillisecondsF() / 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.0;
+    base::TimeDelta duration = end_time - start_time_;
+    if (duration > base::TimeDelta()) {
+      kbps = it->second.sum_size / duration.InMillisecondsF() * 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;
+    base::TimeDelta duration = end_time - start_time_;
+    if (duration > base::TimeDelta()) {
+      kbps = it->second.sum_size / duration.InMillisecondsF() * 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_fraction = static_cast<double>(retransmitted_count) /
+                                (sent_count + retransmitted_count);
+  stats_map->insert(
+      std::make_pair(PACKET_LOSS_FRACTION, packet_loss_fraction));
+}
+
+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