media/cast/logging/stats_event_subscriber_unittest.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/memory/ref_counted.h"
   6 #include "base/memory/scoped_ptr.h"
   7 #include "base/rand_util.h"
   8 #include "base/test/simple_test_tick_clock.h"
   9 #include "base/time/tick_clock.h"
  10 #include "media/cast/cast_environment.h"
  11 #include "media/cast/logging/logging_defines.h"
  12 #include "media/cast/logging/stats_event_subscriber.h"
  13 #include "media/cast/test/fake_receiver_time_offset_estimator.h"
  14 #include "media/cast/test/fake_single_thread_task_runner.h"
  15 #include "testing/gtest/include/gtest/gtest.h"
  16
  17 namespace {
  18 const int kReceiverOffsetSecs = 100;
  19 }
  20
  21 namespace media {
  22 namespace cast {
  23
  24 class StatsEventSubscriberTest : public ::testing::Test {
  25  protected:
  26   StatsEventSubscriberTest()
  27       : sender_clock_(new base::SimpleTestTickClock()),
  28         task_runner_(new test::FakeSingleThreadTaskRunner(sender_clock_)),
  29         cast_environment_(new CastEnvironment(
  30             scoped_ptr<base::TickClock>(sender_clock_).Pass(),
  31             task_runner_,
  32             task_runner_,
  33             task_runner_)),
  34         fake_offset_estimator_(
  35             base::TimeDelta::FromSeconds(kReceiverOffsetSecs)) {
  36     receiver_clock_.Advance(base::TimeDelta::FromSeconds(kReceiverOffsetSecs));
  37     cast_environment_->Logging()->AddRawEventSubscriber(
  38         &fake_offset_estimator_);
  39   }
  40
  41   virtual ~StatsEventSubscriberTest() {
  42     if (subscriber_.get())
  43       cast_environment_->Logging()->RemoveRawEventSubscriber(subscriber_.get());
  44     cast_environment_->Logging()->RemoveRawEventSubscriber(
  45         &fake_offset_estimator_);
  46   }
  47
  48   void AdvanceClocks(base::TimeDelta delta) {
  49     sender_clock_->Advance(delta);
  50     receiver_clock_.Advance(delta);
  51   }
  52
  53   void Init(EventMediaType event_media_type) {
  54     DCHECK(!subscriber_.get());
  55     subscriber_.reset(new StatsEventSubscriber(
  56         event_media_type, cast_environment_->Clock(), &fake_offset_estimator_));
  57     cast_environment_->Logging()->AddRawEventSubscriber(subscriber_.get());
  58   }
  59
  60   base::SimpleTestTickClock* sender_clock_;  // Owned by CastEnvironment.
  61   base::SimpleTestTickClock receiver_clock_;
  62   scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_;
  63   scoped_refptr<CastEnvironment> cast_environment_;
  64   test::FakeReceiverTimeOffsetEstimator fake_offset_estimator_;
  65   scoped_ptr<StatsEventSubscriber> subscriber_;
  66 };
  67
  68 TEST_F(StatsEventSubscriberTest, Capture) {
  69   Init(VIDEO_EVENT);
  70
  71   uint32 rtp_timestamp = 0;
  72   uint32 frame_id = 0;
  73   int num_frames = 10;
  74   base::TimeTicks start_time = sender_clock_->NowTicks();
  75   for (int i = 0; i < num_frames; i++) {
  76     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
  77                                                    FRAME_CAPTURE_BEGIN,
  78                                                    VIDEO_EVENT,
  79                                                    rtp_timestamp,
  80                                                    frame_id);
  81
  82     AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
  83     rtp_timestamp += 90;
  84     frame_id++;
  85   }
  86
  87   base::TimeTicks end_time = sender_clock_->NowTicks();
  88
  89   StatsEventSubscriber::StatsMap stats_map;
  90   subscriber_->GetStatsInternal(&stats_map);
  91
  92   StatsEventSubscriber::StatsMap::iterator it =
  93       stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
  94   ASSERT_NE(it, stats_map.end());
  95
  96   base::TimeDelta duration = end_time - start_time;
  97   EXPECT_DOUBLE_EQ(
  98       it->second,
  99       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 100 }
 101
 102 TEST_F(StatsEventSubscriberTest, Encode) {
 103   Init(VIDEO_EVENT);
 104
 105   uint32 rtp_timestamp = 0;
 106   uint32 frame_id = 0;
 107   int num_frames = 10;
 108   base::TimeTicks start_time = sender_clock_->NowTicks();
 109   int total_size = 0;
 110   for (int i = 0; i < num_frames; i++) {
 111     int size = 1000 + base::RandInt(-100, 100);
 112     total_size += size;
 113     cast_environment_->Logging()->InsertEncodedFrameEvent(
 114         sender_clock_->NowTicks(),
 115         FRAME_ENCODED, VIDEO_EVENT,
 116         rtp_timestamp,
 117         frame_id,
 118         size,
 119         true,
 120         5678);
 121
 122     AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 123     rtp_timestamp += 90;
 124     frame_id++;
 125   }
 126
 127   base::TimeTicks end_time = sender_clock_->NowTicks();
 128
 129   StatsEventSubscriber::StatsMap stats_map;
 130   subscriber_->GetStatsInternal(&stats_map);
 131
 132   StatsEventSubscriber::StatsMap::iterator it =
 133       stats_map.find(StatsEventSubscriber::ENCODE_FPS);
 134   ASSERT_NE(it, stats_map.end());
 135
 136   base::TimeDelta duration = end_time - start_time;
 137   EXPECT_DOUBLE_EQ(
 138       it->second,
 139       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 140
 141   it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
 142   ASSERT_NE(it, stats_map.end());
 143
 144   EXPECT_DOUBLE_EQ(it->second,
 145               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 146 }
 147
 148 TEST_F(StatsEventSubscriberTest, Decode) {
 149   Init(VIDEO_EVENT);
 150
 151   uint32 rtp_timestamp = 0;
 152   uint32 frame_id = 0;
 153   int num_frames = 10;
 154   base::TimeTicks start_time = sender_clock_->NowTicks();
 155   for (int i = 0; i < num_frames; i++) {
 156     cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(),
 157                                                    FRAME_DECODED, VIDEO_EVENT,
 158                                                    rtp_timestamp,
 159                                                    frame_id);
 160
 161     AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
 162     rtp_timestamp += 90;
 163     frame_id++;
 164   }
 165
 166   base::TimeTicks end_time = sender_clock_->NowTicks();
 167
 168   StatsEventSubscriber::StatsMap stats_map;
 169   subscriber_->GetStatsInternal(&stats_map);
 170
 171   StatsEventSubscriber::StatsMap::iterator it =
 172       stats_map.find(StatsEventSubscriber::DECODE_FPS);
 173   ASSERT_NE(it, stats_map.end());
 174
 175   base::TimeDelta duration = end_time - start_time;
 176   EXPECT_DOUBLE_EQ(
 177       it->second,
 178       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 179 }
 180
 181 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
 182   Init(VIDEO_EVENT);
 183
 184   uint32 rtp_timestamp = 0;
 185   uint32 frame_id = 0;
 186   int num_frames = 10;
 187   int total_delay_ms = 0;
 188   for (int i = 0; i < num_frames; i++) {
 189     int delay_ms = base::RandInt(-50, 50);
 190     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
 191     total_delay_ms += delay_ms;
 192     cast_environment_->Logging()->InsertFrameEventWithDelay(
 193         receiver_clock_.NowTicks(),
 194         FRAME_PLAYOUT,
 195         VIDEO_EVENT,
 196         rtp_timestamp,
 197         frame_id,
 198         delay);
 199
 200     AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
 201     rtp_timestamp += 90;
 202     frame_id++;
 203   }
 204
 205   StatsEventSubscriber::StatsMap stats_map;
 206   subscriber_->GetStatsInternal(&stats_map);
 207
 208   StatsEventSubscriber::StatsMap::iterator it =
 209       stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS);
 210   ASSERT_NE(it, stats_map.end());
 211
 212   EXPECT_DOUBLE_EQ(
 213       it->second, static_cast<double>(total_delay_ms) / num_frames);
 214 }
 215
 216 TEST_F(StatsEventSubscriberTest, E2ELatency) {
 217   Init(VIDEO_EVENT);
 218
 219   uint32 rtp_timestamp = 0;
 220   uint32 frame_id = 0;
 221   int num_frames = 10;
 222   base::TimeDelta total_latency;
 223   for (int i = 0; i < num_frames; i++) {
 224     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 225                                                    FRAME_CAPTURE_BEGIN,
 226                                                    VIDEO_EVENT,
 227                                                    rtp_timestamp,
 228                                                    frame_id);
 229
 230     int latency_micros = 100000 + base::RandInt(-5000, 50000);
 231     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 232     AdvanceClocks(latency);
 233
 234     int delay_micros = base::RandInt(-50000, 50000);
 235     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
 236     total_latency += latency + delay;
 237
 238     cast_environment_->Logging()->InsertFrameEventWithDelay(
 239         receiver_clock_.NowTicks(),
 240         FRAME_PLAYOUT,
 241         VIDEO_EVENT,
 242         rtp_timestamp,
 243         frame_id,
 244         delay);
 245
 246     rtp_timestamp += 90;
 247     frame_id++;
 248   }
 249
 250   StatsEventSubscriber::StatsMap stats_map;
 251   subscriber_->GetStatsInternal(&stats_map);
 252
 253   StatsEventSubscriber::StatsMap::iterator it =
 254       stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
 255   ASSERT_NE(it, stats_map.end());
 256
 257   EXPECT_DOUBLE_EQ(
 258       it->second, total_latency.InMillisecondsF() / num_frames);
 259 }
 260
 261 TEST_F(StatsEventSubscriberTest, Packets) {
 262   Init(VIDEO_EVENT);
 263
 264   uint32 rtp_timestamp = 0;
 265   int num_packets = 10;
 266   int num_latency_recorded_packets = 0;
 267   base::TimeTicks start_time = sender_clock_->NowTicks();
 268   int total_size = 0;
 269   int retransmit_total_size = 0;
 270   base::TimeDelta total_latency;
 271   int num_packets_sent = 0;
 272   int num_packets_retransmitted = 0;
 273   // Every 2nd packet will be retransmitted once.
 274   // Every 4th packet will be retransmitted twice.
 275   // Every 8th packet will be retransmitted 3 times.
 276   for (int i = 0; i < num_packets; i++) {
 277     int size = 1000 + base::RandInt(-100, 100);
 278     total_size += size;
 279
 280     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
 281                                                     PACKET_SENT_TO_NETWORK,
 282                                                     VIDEO_EVENT,
 283                                                     rtp_timestamp,
 284                                                     0,
 285                                                     i,
 286                                                     num_packets - 1,
 287                                                     size);
 288     num_packets_sent++;
 289
 290     int latency_micros = 20000 + base::RandInt(-10000, 10000);
 291     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 292     // Latency is only recorded for packets that aren't retransmitted.
 293     if (i % 2 != 0) {
 294       total_latency += latency;
 295       num_latency_recorded_packets++;
 296     }
 297
 298     AdvanceClocks(latency);
 299
 300     base::TimeTicks received_time = receiver_clock_.NowTicks();
 301
 302     // Retransmission 1.
 303     AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
 304     if (i % 2 == 0) {
 305       cast_environment_->Logging()->InsertPacketEvent(
 306           receiver_clock_.NowTicks(),
 307           PACKET_RETRANSMITTED,
 308           VIDEO_EVENT,
 309           rtp_timestamp,
 310           0,
 311           i,
 312           num_packets - 1,
 313           size);
 314       retransmit_total_size += size;
 315       num_packets_sent++;
 316       num_packets_retransmitted++;
 317     }
 318
 319     // Retransmission 2.
 320     AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
 321     if (i % 4 == 0) {
 322       cast_environment_->Logging()->InsertPacketEvent(
 323           receiver_clock_.NowTicks(),
 324           PACKET_RETRANSMITTED,
 325           VIDEO_EVENT,
 326           rtp_timestamp,
 327           0,
 328           i,
 329           num_packets - 1,
 330           size);
 331       retransmit_total_size += size;
 332       num_packets_sent++;
 333       num_packets_retransmitted++;
 334     }
 335
 336     // Retransmission 3.
 337     AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
 338     if (i % 8 == 0) {
 339       cast_environment_->Logging()->InsertPacketEvent(
 340           receiver_clock_.NowTicks(),
 341           PACKET_RETRANSMITTED,
 342           VIDEO_EVENT,
 343           rtp_timestamp,
 344           0,
 345           i,
 346           num_packets - 1,
 347           size);
 348       retransmit_total_size += size;
 349       num_packets_sent++;
 350       num_packets_retransmitted++;
 351     }
 352
 353     cast_environment_->Logging()->InsertPacketEvent(received_time,
 354                                                     PACKET_RECEIVED,
 355                                                     VIDEO_EVENT,
 356                                                     rtp_timestamp,
 357                                                     0,
 358                                                     i,
 359                                                     num_packets - 1,
 360                                                     size);
 361   }
 362
 363   base::TimeTicks end_time = sender_clock_->NowTicks();
 364   base::TimeDelta duration = end_time - start_time;
 365
 366   StatsEventSubscriber::StatsMap stats_map;
 367   subscriber_->GetStatsInternal(&stats_map);
 368
 369   // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS,
 370   // and PACKET_LOSS_FRACTION.
 371   StatsEventSubscriber::StatsMap::iterator it =
 372       stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
 373   ASSERT_NE(it, stats_map.end());
 374
 375   EXPECT_DOUBLE_EQ(
 376       it->second,
 377       total_latency.InMillisecondsF() / num_latency_recorded_packets);
 378
 379   it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
 380   ASSERT_NE(it, stats_map.end());
 381
 382   EXPECT_DOUBLE_EQ(it->second,
 383               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 384
 385   it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
 386   ASSERT_NE(it, stats_map.end());
 387
 388   EXPECT_DOUBLE_EQ(it->second,
 389               static_cast<double>(retransmit_total_size) /
 390                   duration.InMillisecondsF() * 8);
 391
 392   it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION);
 393   ASSERT_NE(it, stats_map.end());
 394
 395   EXPECT_DOUBLE_EQ(
 396       it->second,
 397       static_cast<double>(num_packets_retransmitted) / num_packets_sent);
 398 }
 399
 400 }  // namespace cast
 401 }  // namespace media