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

* Total frames captured
* Total frames dropped
* Total frames late
* Total packet count
* Total packet retransmission
* Total packet retransmission rejected

BUG=403921

Review URL: https://codereview.chromium.org/472203002

Cr-Commit-Position: refs/heads/master@{#289879}
git-svn-id: svn://svn.chromium.org/chrome/trunk/src@289879 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 188 insertions, 33 deletions

diff --git a/media/cast/logging/stats_event_subscriber.cc b/media/cast/logging/stats_event_subscriber.cc
index 9e3226a..03c669c 100644
--- a/media/cast/logging/stats_event_subscriber.cc
+++ b/media/cast/logging/stats_event_subscriber.cc
@@ -19,7 +19,6 @@ namespace {
 using media::cast::CastLoggingEvent;
 using media::cast::EventMediaType;
 
-const size_t kMaxFrameEventTimeMapSize = 100;
 const size_t kMaxPacketEventTimeMapSize = 1000;
 
 bool IsReceiverEvent(CastLoggingEvent event) {
@@ -39,7 +38,9 @@ StatsEventSubscriber::StatsEventSubscriber(
       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;
@@ -71,9 +72,13 @@ void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
   }
 
   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))
@@ -138,7 +143,9 @@ void StatsEventSubscriber::Reset() {
   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();
@@ -159,6 +166,12 @@ const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
     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 "";
@@ -188,6 +201,12 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
                             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 =
@@ -208,6 +227,10 @@ void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
         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) {
@@ -222,12 +245,22 @@ bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
   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) {
@@ -235,15 +268,15 @@ void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
   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_++;
 }
 
@@ -323,6 +356,24 @@ void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
   }
 }
 
+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()) {
@@ -396,5 +447,11 @@ 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
diff --git a/media/cast/logging/stats_event_subscriber.h b/media/cast/logging/stats_event_subscriber.h
index 173378a..06ceaca9 100644
--- a/media/cast/logging/stats_event_subscriber.h
+++ b/media/cast/logging/stats_event_subscriber.h
@@ -49,13 +49,15 @@ class StatsEventSubscriber : public RawEventSubscriber {
  private:
   friend class StatsEventSubscriberTest;
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, EmptyStats);
-  FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Capture);
+  FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, CaptureEncode);
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Encode);
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Decode);
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, PlayoutDelay);
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, E2ELatency);
   FRIEND_TEST_ALL_PREFIXES(StatsEventSubscriberTest, Packets);
 
+  static const size_t kMaxFrameInfoMapSize = 100;
+
   // Generic statistics given the raw data. More specific data (e.g. frame rate
   // and bit rate) can be computed given the basic metrics.
   // Some of the metrics will only be set when applicable, e.g. delay and size.
@@ -85,8 +87,7 @@ class StatsEventSubscriber : public RawEventSubscriber {
     // TODO(imcheng): This stat is not populated yet because we do not have
     // the time when encode started. Record it in FRAME_ENCODED event.
     AVG_ENCODE_TIME_MS,
-    // Average playout delay in milliseconds, with target delay already
-    // accounted for. Ideally, every frame should have a playout delay of 0.
+    // Average playout delay in milliseconds.
     AVG_PLAYOUT_DELAY_MS,
     // Duration from when a packet is transmitted to when it is received.
     // This measures latency from sender to receiver.
@@ -102,11 +103,31 @@ class StatsEventSubscriber : public RawEventSubscriber {
     // Fraction of packet loss.
     PACKET_LOSS_FRACTION,
     // Duration in milliseconds since last receiver response.
-    MS_SINCE_LAST_RECEIVER_RESPONSE
+    MS_SINCE_LAST_RECEIVER_RESPONSE,
+    // Number of frames captured.
+    NUM_FRAMES_CAPTURED,
+    // Number of frames dropped by encoder.
+    NUM_FRAMES_DROPPED_BY_ENCODER,
+    // Number of late frames.
+    NUM_FRAMES_LATE,
+    // Number of packets that were sent (not retransmitted).
+    NUM_PACKETS_SENT,
+    // Number of packets that were retransmitted.
+    NUM_PACKETS_RETRANSMITTED,
+    // Number of packets that had their retransmission cancelled.
+    NUM_PACKETS_RTX_REJECTED,
+  };
+
+  struct FrameInfo {
+    explicit FrameInfo(base::TimeTicks capture_time);
+    ~FrameInfo();
+
+    base::TimeTicks capture_time;
+    bool encoded;
   };
 
   typedef std::map<CastStat, double> StatsMap;
-  typedef std::map<RtpTimestamp, base::TimeTicks> FrameEventTimeMap;
+  typedef std::map<RtpTimestamp, FrameInfo> FrameInfoMap;
   typedef std::map<
       std::pair<RtpTimestamp, uint16>,
       std::pair<base::TimeTicks, CastLoggingEvent> >
@@ -120,7 +141,8 @@ class StatsEventSubscriber : public RawEventSubscriber {
   void GetStatsInternal(StatsMap* stats_map) const;
 
   bool GetReceiverOffset(base::TimeDelta* offset);
-  void RecordFrameCapturedTime(const FrameEvent& frame_event);
+  void RecordFrameCaptureTime(const FrameEvent& frame_event);
+  void MarkAsEncoded(RtpTimestamp rtp_timestamp);
   void RecordE2ELatency(const FrameEvent& frame_event);
   void RecordPacketSentTime(const PacketEvent& packet_event);
   void ErasePacketSentTime(const PacketEvent& packet_event);
@@ -131,6 +153,12 @@ class StatsEventSubscriber : public RawEventSubscriber {
                        CastLoggingEvent event,
                        CastStat stat,
                        StatsMap* stats_map) const;
+  void PopulateFrameCountStat(CastLoggingEvent event,
+                              CastStat stat,
+                              StatsMap* stats_map) const;
+  void PopulatePacketCountStat(CastLoggingEvent event,
+                               CastStat stat,
+                               StatsMap* stats_map) const;
   void PopulatePlayoutDelayStat(StatsMap* stats_map) const;
   void PopulateFrameBitrateStat(base::TimeTicks now, StatsMap* stats_map) const;
   void PopulatePacketBitrateStat(base::TimeTicks now,
@@ -157,8 +185,11 @@ class StatsEventSubscriber : public RawEventSubscriber {
 
   base::TimeTicks last_response_received_time_;
 
-  // Fixed size map to record when recent frames were captured.
-  FrameEventTimeMap frame_captured_times_;
+  int num_frames_dropped_by_encoder_;
+  int num_frames_late_;
+
+  // Fixed size map to record when recent frames were captured and other info.
+  FrameInfoMap recent_captured_frames_;
 
   // Fixed size map to record when recent packets were sent.
   PacketEventTimeMap packet_sent_times_;
diff --git a/media/cast/logging/stats_event_subscriber_unittest.cc b/media/cast/logging/stats_event_subscriber_unittest.cc
index 09c418b..fe03bc6 100644
--- a/media/cast/logging/stats_event_subscriber_unittest.cc
+++ b/media/cast/logging/stats_event_subscriber_unittest.cc
@@ -65,20 +65,44 @@ class StatsEventSubscriberTest : public ::testing::Test {
   scoped_ptr<StatsEventSubscriber> subscriber_;
 };
 
-TEST_F(StatsEventSubscriberTest, Capture) {
+TEST_F(StatsEventSubscriberTest, CaptureEncode) {
   Init(VIDEO_EVENT);
 
   uint32 rtp_timestamp = 0;
   uint32 frame_id = 0;
-  int num_frames = 10;
+  int extra_frames = 50;
+  // Only the first |extra_frames| frames logged will be taken into account
+  // when computing dropped frames.
+  int num_frames = StatsEventSubscriber::kMaxFrameInfoMapSize + 50;
+  int dropped_frames = 0;
   base::TimeTicks start_time = sender_clock_->NowTicks();
+  // Drop half the frames during the encode step.
   for (int i = 0; i < num_frames; i++) {
     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
                                                    FRAME_CAPTURE_BEGIN,
                                                    VIDEO_EVENT,
                                                    rtp_timestamp,
                                                    frame_id);
-
+    AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
+    cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
+                                                   FRAME_CAPTURE_END,
+                                                   VIDEO_EVENT,
+                                                   rtp_timestamp,
+                                                   frame_id);
+    if (i % 2 == 0) {
+      AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
+      cast_environment_->Logging()->InsertEncodedFrameEvent(
+          sender_clock_->NowTicks(),
+          FRAME_ENCODED,
+          VIDEO_EVENT,
+          rtp_timestamp,
+          frame_id,
+          1024,
+          true,
+          5678);
+    } else if (i < extra_frames) {
+      dropped_frames++;
+    }
     AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
     rtp_timestamp += 90;
     frame_id++;
@@ -97,6 +121,16 @@ TEST_F(StatsEventSubscriberTest, Capture) {
   EXPECT_DOUBLE_EQ(
       it->second,
       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
+
+  it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_CAPTURED);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_frames));
+
+  it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_DROPPED_BY_ENCODER);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, static_cast<double>(dropped_frames));
 }
 
 TEST_F(StatsEventSubscriberTest, Encode) {
@@ -185,10 +219,12 @@ TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
   uint32 frame_id = 0;
   int num_frames = 10;
   int total_delay_ms = 0;
-  for (int i = 0; i < num_frames; i++) {
-    int delay_ms = base::RandInt(-50, 50);
+  int late_frames = 0;
+  for (int i = 0, delay_ms = -50; i < num_frames; i++, delay_ms += 10) {
     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
     total_delay_ms += delay_ms;
+    if (delay_ms <= 0)
+      late_frames++;
     cast_environment_->Logging()->InsertFrameEventWithDelay(
         receiver_clock_.NowTicks(),
         FRAME_PLAYOUT,
@@ -211,6 +247,11 @@ TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
 
   EXPECT_DOUBLE_EQ(
       it->second, static_cast<double>(total_delay_ms) / num_frames);
+
+  it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_LATE);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, late_frames);
 }
 
 TEST_F(StatsEventSubscriberTest, E2ELatency) {
@@ -268,11 +309,12 @@ TEST_F(StatsEventSubscriberTest, Packets) {
   int total_size = 0;
   int retransmit_total_size = 0;
   base::TimeDelta total_latency;
-  int num_packets_sent = 0;
+  int num_packets_transmitted = 0;
   int num_packets_retransmitted = 0;
+  int num_packets_rtx_rejected = 0;
   // Every 2nd packet will be retransmitted once.
   // Every 4th packet will be retransmitted twice.
-  // Every 8th packet will be retransmitted 3 times.
+  // Every 8th packet will be retransmitted 3 times + 1 rejected retransmission.
   for (int i = 0; i < num_packets; i++) {
     int size = 1000 + base::RandInt(-100, 100);
     total_size += size;
@@ -285,7 +327,7 @@ TEST_F(StatsEventSubscriberTest, Packets) {
                                                     i,
                                                     num_packets - 1,
                                                     size);
-    num_packets_sent++;
+    num_packets_transmitted++;
 
     int latency_micros = 20000 + base::RandInt(-10000, 10000);
     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
@@ -312,7 +354,7 @@ TEST_F(StatsEventSubscriberTest, Packets) {
           num_packets - 1,
           size);
       retransmit_total_size += size;
-      num_packets_sent++;
+      num_packets_transmitted++;
       num_packets_retransmitted++;
     }
 
@@ -329,7 +371,7 @@ TEST_F(StatsEventSubscriberTest, Packets) {
           num_packets - 1,
           size);
       retransmit_total_size += size;
-      num_packets_sent++;
+      num_packets_transmitted++;
       num_packets_retransmitted++;
     }
 
@@ -345,9 +387,19 @@ TEST_F(StatsEventSubscriberTest, Packets) {
           i,
           num_packets - 1,
           size);
+      cast_environment_->Logging()->InsertPacketEvent(
+          receiver_clock_.NowTicks(),
+          PACKET_RTX_REJECTED,
+          VIDEO_EVENT,
+          rtp_timestamp,
+          0,
+          i,
+          num_packets - 1,
+          size);
       retransmit_total_size += size;
-      num_packets_sent++;
+      num_packets_transmitted++;
       num_packets_retransmitted++;
+      num_packets_rtx_rejected++;
     }
 
     cast_environment_->Logging()->InsertPacketEvent(received_time,
@@ -394,7 +446,22 @@ TEST_F(StatsEventSubscriberTest, Packets) {
 
   EXPECT_DOUBLE_EQ(
       it->second,
-      static_cast<double>(num_packets_retransmitted) / num_packets_sent);
+      static_cast<double>(num_packets_retransmitted) / num_packets_transmitted);
+
+  it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_SENT);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets));
+
+  it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RETRANSMITTED);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_retransmitted));
+
+  it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RTX_REJECTED);
+  ASSERT_TRUE(it != stats_map.end());
+
+  EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_rtx_rejected));
 }
 
 }  // namespace cast