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

media/cast/logging/stats_event_subscriber_unittest.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 "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/rand_util.h"
 #include "base/test/simple_test_tick_clock.h"
 #include "base/time/tick_clock.h"
 #include "media/cast/cast_environment.h"
@@ skipping 47 matching lines @@
   }
 
   base::SimpleTestTickClock* sender_clock_;  // Owned by CastEnvironment.
   base::SimpleTestTickClock receiver_clock_;
   scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_;
   scoped_refptr<CastEnvironment> cast_environment_;
   test::FakeReceiverTimeOffsetEstimator fake_offset_estimator_;
   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++;
   }
 
   base::TimeTicks end_time = sender_clock_->NowTicks();
 
   StatsEventSubscriber::StatsMap stats_map;
   subscriber_->GetStatsInternal(&stats_map);
 
   StatsEventSubscriber::StatsMap::iterator it =
       stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
   ASSERT_TRUE(it != stats_map.end());
 
   base::TimeDelta duration = end_time - start_time;
   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) {
   Init(VIDEO_EVENT);
 
   uint32 rtp_timestamp = 0;
   uint32 frame_id = 0;
   int num_frames = 10;
   base::TimeTicks start_time = sender_clock_->NowTicks();
   int total_size = 0;
@@ skipping 68 matching lines @@
       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 }
 
 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
   Init(VIDEO_EVENT);
 
   uint32 rtp_timestamp = 0;
   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,
         VIDEO_EVENT,
         rtp_timestamp,
         frame_id,
         delay);
 
     AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
     rtp_timestamp += 90;
     frame_id++;
   }
 
   StatsEventSubscriber::StatsMap stats_map;
   subscriber_->GetStatsInternal(&stats_map);
 
   StatsEventSubscriber::StatsMap::iterator it =
       stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS);
   ASSERT_TRUE(it != stats_map.end());
 
   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) {
   Init(VIDEO_EVENT);
 
   uint32 rtp_timestamp = 0;
   uint32 frame_id = 0;
   int num_frames = 10;
   base::TimeDelta total_latency;
   for (int i = 0; i < num_frames; i++) {
@@ skipping 37 matching lines @@
 TEST_F(StatsEventSubscriberTest, Packets) {
   Init(VIDEO_EVENT);
 
   uint32 rtp_timestamp = 0;
   int num_packets = 10;
   int num_latency_recorded_packets = 0;
   base::TimeTicks start_time = sender_clock_->NowTicks();
   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;
 
     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
                                                     PACKET_SENT_TO_NETWORK,
                                                     VIDEO_EVENT,
                                                     rtp_timestamp,
                                                     0,
                                                     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);
     // Latency is only recorded for packets that aren't retransmitted.
     if (i % 2 != 0) {
       total_latency += latency;
       num_latency_recorded_packets++;
     }
 
     AdvanceClocks(latency);
 
     base::TimeTicks received_time = receiver_clock_.NowTicks();
 
     // Retransmission 1.
     AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
     if (i % 2 == 0) {
       cast_environment_->Logging()->InsertPacketEvent(
           receiver_clock_.NowTicks(),
           PACKET_RETRANSMITTED,
           VIDEO_EVENT,
           rtp_timestamp,
           0,
           i,
           num_packets - 1,
           size);
       retransmit_total_size += size;
-      num_packets_sent++;
+      num_packets_transmitted++;
       num_packets_retransmitted++;
     }
 
     // Retransmission 2.
     AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
     if (i % 4 == 0) {
       cast_environment_->Logging()->InsertPacketEvent(
           receiver_clock_.NowTicks(),
           PACKET_RETRANSMITTED,
           VIDEO_EVENT,
           rtp_timestamp,
           0,
           i,
           num_packets - 1,
           size);
       retransmit_total_size += size;
-      num_packets_sent++;
+      num_packets_transmitted++;
       num_packets_retransmitted++;
     }
 
     // Retransmission 3.
     AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
     if (i % 8 == 0) {
       cast_environment_->Logging()->InsertPacketEvent(
           receiver_clock_.NowTicks(),
           PACKET_RETRANSMITTED,
           VIDEO_EVENT,
           rtp_timestamp,
           0,
           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,
                                                     PACKET_RECEIVED,
                                                     VIDEO_EVENT,
                                                     rtp_timestamp,
                                                     0,
                                                     i,
                                                     num_packets - 1,
                                                     size);
@@ skipping 26 matching lines @@
 
   EXPECT_DOUBLE_EQ(it->second,
               static_cast<double>(retransmit_total_size) /
                   duration.InMillisecondsF() * 8);
 
   it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION);
   ASSERT_TRUE(it != stats_map.end());
 
   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
 }  // namespace media