src/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, CaptureEncode) {
  69   Init(VIDEO_EVENT);
  70
  71   uint32 rtp_timestamp = 0;
  72   uint32 frame_id = 0;
  73   int extra_frames = 50;
  74   // Only the first |extra_frames| frames logged will be taken into account
  75   // when computing dropped frames.
  76   int num_frames = StatsEventSubscriber::kMaxFrameInfoMapSize + 50;
  77   int dropped_frames = 0;
  78   base::TimeTicks start_time = sender_clock_->NowTicks();
  79   // Drop half the frames during the encode step.
  80   for (int i = 0; i < num_frames; i++) {
  81     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
  82                                                    FRAME_CAPTURE_BEGIN,
  83                                                    VIDEO_EVENT,
  84                                                    rtp_timestamp,
  85                                                    frame_id);
  86     AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
  87     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
  88                                                    FRAME_CAPTURE_END,
  89                                                    VIDEO_EVENT,
  90                                                    rtp_timestamp,
  91                                                    frame_id);
  92     if (i % 2 == 0) {
  93       AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
  94       cast_environment_->Logging()->InsertEncodedFrameEvent(
  95           sender_clock_->NowTicks(),
  96           FRAME_ENCODED,
  97           VIDEO_EVENT,
  98           rtp_timestamp,
  99           frame_id,
 100           1024,
 101           true,
 102           5678);
 103     } else if (i < extra_frames) {
 104       dropped_frames++;
 105     }
 106     AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
 107     rtp_timestamp += 90;
 108     frame_id++;
 109   }
 110
 111   base::TimeTicks end_time = sender_clock_->NowTicks();
 112
 113   StatsEventSubscriber::StatsMap stats_map;
 114   subscriber_->GetStatsInternal(&stats_map);
 115
 116   StatsEventSubscriber::StatsMap::iterator it =
 117       stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
 118   ASSERT_TRUE(it != stats_map.end());
 119
 120   base::TimeDelta duration = end_time - start_time;
 121   EXPECT_DOUBLE_EQ(
 122       it->second,
 123       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 124
 125   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_CAPTURED);
 126   ASSERT_TRUE(it != stats_map.end());
 127
 128   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_frames));
 129
 130   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_DROPPED_BY_ENCODER);
 131   ASSERT_TRUE(it != stats_map.end());
 132
 133   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(dropped_frames));
 134 }
 135
 136 TEST_F(StatsEventSubscriberTest, Encode) {
 137   Init(VIDEO_EVENT);
 138
 139   uint32 rtp_timestamp = 0;
 140   uint32 frame_id = 0;
 141   int num_frames = 10;
 142   base::TimeTicks start_time = sender_clock_->NowTicks();
 143   int total_size = 0;
 144   for (int i = 0; i < num_frames; i++) {
 145     int size = 1000 + base::RandInt(-100, 100);
 146     total_size += size;
 147     cast_environment_->Logging()->InsertEncodedFrameEvent(
 148         sender_clock_->NowTicks(),
 149         FRAME_ENCODED, VIDEO_EVENT,
 150         rtp_timestamp,
 151         frame_id,
 152         size,
 153         true,
 154         5678);
 155
 156     AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 157     rtp_timestamp += 90;
 158     frame_id++;
 159   }
 160
 161   base::TimeTicks end_time = sender_clock_->NowTicks();
 162
 163   StatsEventSubscriber::StatsMap stats_map;
 164   subscriber_->GetStatsInternal(&stats_map);
 165
 166   StatsEventSubscriber::StatsMap::iterator it =
 167       stats_map.find(StatsEventSubscriber::ENCODE_FPS);
 168   ASSERT_TRUE(it != stats_map.end());
 169
 170   base::TimeDelta duration = end_time - start_time;
 171   EXPECT_DOUBLE_EQ(
 172       it->second,
 173       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 174
 175   it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
 176   ASSERT_TRUE(it != stats_map.end());
 177
 178   EXPECT_DOUBLE_EQ(it->second,
 179               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 180 }
 181
 182 TEST_F(StatsEventSubscriberTest, Decode) {
 183   Init(VIDEO_EVENT);
 184
 185   uint32 rtp_timestamp = 0;
 186   uint32 frame_id = 0;
 187   int num_frames = 10;
 188   base::TimeTicks start_time = sender_clock_->NowTicks();
 189   for (int i = 0; i < num_frames; i++) {
 190     cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(),
 191                                                    FRAME_DECODED, VIDEO_EVENT,
 192                                                    rtp_timestamp,
 193                                                    frame_id);
 194
 195     AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
 196     rtp_timestamp += 90;
 197     frame_id++;
 198   }
 199
 200   base::TimeTicks end_time = sender_clock_->NowTicks();
 201
 202   StatsEventSubscriber::StatsMap stats_map;
 203   subscriber_->GetStatsInternal(&stats_map);
 204
 205   StatsEventSubscriber::StatsMap::iterator it =
 206       stats_map.find(StatsEventSubscriber::DECODE_FPS);
 207   ASSERT_TRUE(it != stats_map.end());
 208
 209   base::TimeDelta duration = end_time - start_time;
 210   EXPECT_DOUBLE_EQ(
 211       it->second,
 212       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 213 }
 214
 215 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
 216   Init(VIDEO_EVENT);
 217
 218   uint32 rtp_timestamp = 0;
 219   uint32 frame_id = 0;
 220   int num_frames = 10;
 221   int total_delay_ms = 0;
 222   int late_frames = 0;
 223   for (int i = 0, delay_ms = -50; i < num_frames; i++, delay_ms += 10) {
 224     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
 225     total_delay_ms += delay_ms;
 226     if (delay_ms <= 0)
 227       late_frames++;
 228     cast_environment_->Logging()->InsertFrameEventWithDelay(
 229         receiver_clock_.NowTicks(),
 230         FRAME_PLAYOUT,
 231         VIDEO_EVENT,
 232         rtp_timestamp,
 233         frame_id,
 234         delay);
 235
 236     AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
 237     rtp_timestamp += 90;
 238     frame_id++;
 239   }
 240
 241   StatsEventSubscriber::StatsMap stats_map;
 242   subscriber_->GetStatsInternal(&stats_map);
 243
 244   StatsEventSubscriber::StatsMap::iterator it =
 245       stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS);
 246   ASSERT_TRUE(it != stats_map.end());
 247
 248   EXPECT_DOUBLE_EQ(
 249       it->second, static_cast<double>(total_delay_ms) / num_frames);
 250
 251   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_LATE);
 252   ASSERT_TRUE(it != stats_map.end());
 253
 254   EXPECT_DOUBLE_EQ(it->second, late_frames);
 255 }
 256
 257 TEST_F(StatsEventSubscriberTest, E2ELatency) {
 258   Init(VIDEO_EVENT);
 259
 260   uint32 rtp_timestamp = 0;
 261   uint32 frame_id = 0;
 262   int num_frames = 10;
 263   base::TimeDelta total_latency;
 264   for (int i = 0; i < num_frames; i++) {
 265     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 266                                                    FRAME_CAPTURE_BEGIN,
 267                                                    VIDEO_EVENT,
 268                                                    rtp_timestamp,
 269                                                    frame_id);
 270
 271     int latency_micros = 100000 + base::RandInt(-5000, 50000);
 272     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 273     AdvanceClocks(latency);
 274
 275     int delay_micros = base::RandInt(-50000, 50000);
 276     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
 277     total_latency += latency + delay;
 278
 279     cast_environment_->Logging()->InsertFrameEventWithDelay(
 280         receiver_clock_.NowTicks(),
 281         FRAME_PLAYOUT,
 282         VIDEO_EVENT,
 283         rtp_timestamp,
 284         frame_id,
 285         delay);
 286
 287     rtp_timestamp += 90;
 288     frame_id++;
 289   }
 290
 291   StatsEventSubscriber::StatsMap stats_map;
 292   subscriber_->GetStatsInternal(&stats_map);
 293
 294   StatsEventSubscriber::StatsMap::iterator it =
 295       stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
 296   ASSERT_TRUE(it != stats_map.end());
 297
 298   EXPECT_DOUBLE_EQ(
 299       it->second, total_latency.InMillisecondsF() / num_frames);
 300 }
 301
 302 TEST_F(StatsEventSubscriberTest, Packets) {
 303   Init(VIDEO_EVENT);
 304
 305   uint32 rtp_timestamp = 0;
 306   int num_packets = 10;
 307   int num_latency_recorded_packets = 0;
 308   base::TimeTicks start_time = sender_clock_->NowTicks();
 309   int total_size = 0;
 310   int retransmit_total_size = 0;
 311   base::TimeDelta total_latency;
 312   int num_packets_transmitted = 0;
 313   int num_packets_retransmitted = 0;
 314   int num_packets_rtx_rejected = 0;
 315   // Every 2nd packet will be retransmitted once.
 316   // Every 4th packet will be retransmitted twice.
 317   // Every 8th packet will be retransmitted 3 times + 1 rejected retransmission.
 318   for (int i = 0; i < num_packets; i++) {
 319     int size = 1000 + base::RandInt(-100, 100);
 320     total_size += size;
 321
 322     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
 323                                                     PACKET_SENT_TO_NETWORK,
 324                                                     VIDEO_EVENT,
 325                                                     rtp_timestamp,
 326                                                     0,
 327                                                     i,
 328                                                     num_packets - 1,
 329                                                     size);
 330     num_packets_transmitted++;
 331
 332     int latency_micros = 20000 + base::RandInt(-10000, 10000);
 333     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 334     // Latency is only recorded for packets that aren't retransmitted.
 335     if (i % 2 != 0) {
 336       total_latency += latency;
 337       num_latency_recorded_packets++;
 338     }
 339
 340     AdvanceClocks(latency);
 341
 342     base::TimeTicks received_time = receiver_clock_.NowTicks();
 343
 344     // Retransmission 1.
 345     AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
 346     if (i % 2 == 0) {
 347       cast_environment_->Logging()->InsertPacketEvent(
 348           receiver_clock_.NowTicks(),
 349           PACKET_RETRANSMITTED,
 350           VIDEO_EVENT,
 351           rtp_timestamp,
 352           0,
 353           i,
 354           num_packets - 1,
 355           size);
 356       retransmit_total_size += size;
 357       num_packets_transmitted++;
 358       num_packets_retransmitted++;
 359     }
 360
 361     // Retransmission 2.
 362     AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
 363     if (i % 4 == 0) {
 364       cast_environment_->Logging()->InsertPacketEvent(
 365           receiver_clock_.NowTicks(),
 366           PACKET_RETRANSMITTED,
 367           VIDEO_EVENT,
 368           rtp_timestamp,
 369           0,
 370           i,
 371           num_packets - 1,
 372           size);
 373       retransmit_total_size += size;
 374       num_packets_transmitted++;
 375       num_packets_retransmitted++;
 376     }
 377
 378     // Retransmission 3.
 379     AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
 380     if (i % 8 == 0) {
 381       cast_environment_->Logging()->InsertPacketEvent(
 382           receiver_clock_.NowTicks(),
 383           PACKET_RETRANSMITTED,
 384           VIDEO_EVENT,
 385           rtp_timestamp,
 386           0,
 387           i,
 388           num_packets - 1,
 389           size);
 390       cast_environment_->Logging()->InsertPacketEvent(
 391           receiver_clock_.NowTicks(),
 392           PACKET_RTX_REJECTED,
 393           VIDEO_EVENT,
 394           rtp_timestamp,
 395           0,
 396           i,
 397           num_packets - 1,
 398           size);
 399       retransmit_total_size += size;
 400       num_packets_transmitted++;
 401       num_packets_retransmitted++;
 402       num_packets_rtx_rejected++;
 403     }
 404
 405     cast_environment_->Logging()->InsertPacketEvent(received_time,
 406                                                     PACKET_RECEIVED,
 407                                                     VIDEO_EVENT,
 408                                                     rtp_timestamp,
 409                                                     0,
 410                                                     i,
 411                                                     num_packets - 1,
 412                                                     size);
 413   }
 414
 415   base::TimeTicks end_time = sender_clock_->NowTicks();
 416   base::TimeDelta duration = end_time - start_time;
 417
 418   StatsEventSubscriber::StatsMap stats_map;
 419   subscriber_->GetStatsInternal(&stats_map);
 420
 421   // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS,
 422   // and PACKET_LOSS_FRACTION.
 423   StatsEventSubscriber::StatsMap::iterator it =
 424       stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
 425   ASSERT_TRUE(it != stats_map.end());
 426
 427   EXPECT_DOUBLE_EQ(
 428       it->second,
 429       total_latency.InMillisecondsF() / num_latency_recorded_packets);
 430
 431   it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
 432   ASSERT_TRUE(it != stats_map.end());
 433
 434   EXPECT_DOUBLE_EQ(it->second,
 435               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 436
 437   it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
 438   ASSERT_TRUE(it != stats_map.end());
 439
 440   EXPECT_DOUBLE_EQ(it->second,
 441               static_cast<double>(retransmit_total_size) /
 442                   duration.InMillisecondsF() * 8);
 443
 444   it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION);
 445   ASSERT_TRUE(it != stats_map.end());
 446
 447   EXPECT_DOUBLE_EQ(
 448       it->second,
 449       static_cast<double>(num_packets_retransmitted) / num_packets_transmitted);
 450
 451   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_SENT);
 452   ASSERT_TRUE(it != stats_map.end());
 453
 454   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets));
 455
 456   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RETRANSMITTED);
 457   ASSERT_TRUE(it != stats_map.end());
 458
 459   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_retransmitted));
 460
 461   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RTX_REJECTED);
 462   ASSERT_TRUE(it != stats_map.end());
 463
 464   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_rtx_rejected));
 465 }
 466
 467 }  // namespace cast
 468 }  // namespace media