Cast streaming logging: Log additional stats for the GetStats() API.

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 {
 
 namespace {
 
 using media::cast::CastLoggingEvent;
 using media::cast::EventMediaType;
 
-const size_t kMaxFrameEventTimeMapSize = 100;
 const size_t kMaxPacketEventTimeMapSize = 1000;
 
 bool IsReceiverEvent(CastLoggingEvent event) {
   return event == FRAME_DECODED
       || event == FRAME_PLAYOUT
       || event == FRAME_ACK_SENT
       || event == PACKET_RECEIVED;
 }
 
 }  // 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) {
+      e2e_latency_datapoints_(0),
+      num_frames_dropped_by_encoder_(0),
+      num_frames_late_(0) {
   DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
   base::TimeTicks now = clock_->NowTicks();
   start_time_ = now;
   last_response_received_time_ = base::TimeTicks();
 }
 
 StatsEventSubscriber::~StatsEventSubscriber() {
   DCHECK(thread_checker_.CalledOnValidThread());
 }
 
@@ skipping 11 matching lines @@
     stats.sum_size = frame_event.size;
     stats.sum_delay = frame_event.delay_delta;
     frame_stats_.insert(std::make_pair(type, stats));
   } else {
     ++(it->second.event_counter);
     it->second.sum_size += frame_event.size;
     it->second.sum_delay += frame_event.delay_delta;
   }
 
   if (type == FRAME_CAPTURE_BEGIN) {
-    RecordFrameCapturedTime(frame_event);
+    RecordFrameCaptureTime(frame_event);
+  } else if (type == FRAME_ENCODED) {
+    MarkAsEncoded(frame_event.rtp_timestamp);
   } else if (type == FRAME_PLAYOUT) {
     RecordE2ELatency(frame_event);
+    if (frame_event.delay_delta <= base::TimeDelta())
+      num_frames_late_++;
   }
 
   if (IsReceiverEvent(type))
     UpdateLastResponseTime(frame_event.timestamp);
 }
 
 void StatsEventSubscriber::OnReceivePacketEvent(
     const PacketEvent& packet_event) {
   DCHECK(thread_checker_.CalledOnValidThread());
 
@@ skipping 44 matching lines @@
 
 void StatsEventSubscriber::Reset() {
   DCHECK(thread_checker_.CalledOnValidThread());
 
   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();
+  num_frames_dropped_by_encoder_ = 0;
+  num_frames_late_ = 0;
+  recent_captured_frames_.clear();
   packet_sent_times_.clear();
   start_time_ = clock_->NowTicks();
   last_response_received_time_ = base::TimeTicks();
 }
 
 // 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);
+    STAT_ENUM_TO_STRING(NUM_FRAMES_CAPTURED);
+    STAT_ENUM_TO_STRING(NUM_FRAMES_DROPPED_BY_ENCODER);
+    STAT_ENUM_TO_STRING(NUM_FRAMES_LATE);
+    STAT_ENUM_TO_STRING(NUM_PACKETS_SENT);
+    STAT_ENUM_TO_STRING(NUM_PACKETS_RETRANSMITTED);
+    STAT_ENUM_TO_STRING(NUM_PACKETS_RTX_REJECTED);
   }
   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, FRAME_CAPTURE_BEGIN, CAPTURE_FPS, stats_map);
   PopulateFpsStat(
       end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
   PopulateFpsStat(
       end_time, FRAME_DECODED, DECODE_FPS, stats_map);
   PopulatePlayoutDelayStat(stats_map);
   PopulateFrameBitrateStat(end_time, stats_map);
   PopulatePacketBitrateStat(end_time,
                             PACKET_SENT_TO_NETWORK,
                             TRANSMISSION_KBPS,
                             stats_map);
   PopulatePacketBitrateStat(end_time,
                             PACKET_RETRANSMITTED,
                             RETRANSMISSION_KBPS,
                             stats_map);
   PopulatePacketLossPercentageStat(stats_map);
+  PopulateFrameCountStat(FRAME_CAPTURE_END, NUM_FRAMES_CAPTURED, stats_map);
+  PopulatePacketCountStat(PACKET_SENT_TO_NETWORK, NUM_PACKETS_SENT, stats_map);
+  PopulatePacketCountStat(
+      PACKET_RETRANSMITTED, NUM_PACKETS_RETRANSMITTED, stats_map);
+  PopulatePacketCountStat(
+      PACKET_RTX_REJECTED, NUM_PACKETS_RTX_REJECTED, 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));
   }
 
   if (!last_response_received_time_.is_null()) {
     stats_map->insert(
         std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
         (end_time - last_response_received_time_).InMillisecondsF()));
   }
+
+  stats_map->insert(std::make_pair(NUM_FRAMES_DROPPED_BY_ENCODER,
+                                   num_frames_dropped_by_encoder_));
+  stats_map->insert(std::make_pair(NUM_FRAMES_LATE, num_frames_late_));
 }
 
 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(
+void StatsEventSubscriber::RecordFrameCaptureTime(
     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());
+  recent_captured_frames_.insert(std::make_pair(
+      frame_event.rtp_timestamp, FrameInfo(frame_event.timestamp)));
+  if (recent_captured_frames_.size() > kMaxFrameInfoMapSize) {
+    FrameInfoMap::iterator erase_it = recent_captured_frames_.begin();
+    if (!erase_it->second.encoded)
+      num_frames_dropped_by_encoder_++;
+    recent_captured_frames_.erase(erase_it);
+  }
+}
+
+void StatsEventSubscriber::MarkAsEncoded(RtpTimestamp rtp_timestamp) {
+  FrameInfoMap::iterator it = recent_captured_frames_.find(rtp_timestamp);
+  if (it != recent_captured_frames_.end())
+    it->second.encoded = true;
 }
 
 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())
+  FrameInfoMap::iterator it =
+      recent_captured_frames_.find(frame_event.rtp_timestamp);
+  if (it == recent_captured_frames_.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;
+  total_e2e_latency_ += playout_time - it->second.capture_time;
   e2e_latency_datapoints_++;
 }
 
 void StatsEventSubscriber::UpdateLastResponseTime(
     base::TimeTicks receiver_time) {
   base::TimeDelta receiver_offset;
   if (!GetReceiverOffset(&receiver_offset))
     return;
   base::TimeTicks sender_time = receiver_time - receiver_offset;
   last_response_received_time_ = sender_time;
@@ skipping 59 matching lines @@
   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));
   }
 }
 
+void StatsEventSubscriber::PopulateFrameCountStat(CastLoggingEvent event,
+                                                  CastStat stat,
+                                                  StatsMap* stats_map) const {
+  FrameStatsMap::const_iterator it = frame_stats_.find(event);
+  if (it != frame_stats_.end()) {
+    stats_map->insert(std::make_pair(stat, it->second.event_counter));
+  }
+}
+
+void StatsEventSubscriber::PopulatePacketCountStat(CastLoggingEvent event,
+                                                   CastStat stat,
+                                                   StatsMap* stats_map) const {
+  PacketStatsMap::const_iterator it = packet_stats_.find(event);
+  if (it != packet_stats_.end()) {
+    stats_map->insert(std::make_pair(stat, it->second.event_counter));
+  }
+}
+
 void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
   FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_PLAYOUT);
   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));
   }
@@ skipping 53 matching lines @@
 }
 
 StatsEventSubscriber::FrameLogStats::FrameLogStats()
     : event_counter(0), sum_size(0) {}
 StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
 
 StatsEventSubscriber::PacketLogStats::PacketLogStats()
     : event_counter(0), sum_size(0) {}
 StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
 
+StatsEventSubscriber::FrameInfo::FrameInfo(base::TimeTicks capture_time)
+    : capture_time(capture_time), encoded(false) {
+}
+StatsEventSubscriber::FrameInfo::~FrameInfo() {
+}
+
 }  // namespace cast
 }  // namespace media