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   ~StatsEventSubscriberTest() override {
  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           9.10,
 104           11.12);
 105     } else if (i < extra_frames) {
 106       dropped_frames++;
 107     }
 108     AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
 109     rtp_timestamp += 90;
 110     frame_id++;
 111   }
 112
 113   base::TimeTicks end_time = sender_clock_->NowTicks();
 114
 115   StatsEventSubscriber::StatsMap stats_map;
 116   subscriber_->GetStatsInternal(&stats_map);
 117
 118   StatsEventSubscriber::StatsMap::iterator it =
 119       stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
 120   ASSERT_TRUE(it != stats_map.end());
 121
 122   base::TimeDelta duration = end_time - start_time;
 123   EXPECT_DOUBLE_EQ(
 124       it->second,
 125       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 126
 127   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_CAPTURED);
 128   ASSERT_TRUE(it != stats_map.end());
 129
 130   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_frames));
 131
 132   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_DROPPED_BY_ENCODER);
 133   ASSERT_TRUE(it != stats_map.end());
 134
 135   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(dropped_frames));
 136
 137   it = stats_map.find(StatsEventSubscriber::AVG_CAPTURE_LATENCY_MS);
 138   ASSERT_TRUE(it != stats_map.end());
 139
 140   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(0.01));
 141 }
 142
 143 TEST_F(StatsEventSubscriberTest, Encode) {
 144   Init(VIDEO_EVENT);
 145
 146   uint32 rtp_timestamp = 0;
 147   uint32 frame_id = 0;
 148   int num_frames = 10;
 149   base::TimeTicks start_time = sender_clock_->NowTicks();
 150   AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 151   base::TimeTicks first_event_time = sender_clock_->NowTicks();
 152   base::TimeTicks last_event_time;
 153   int total_size = 0;
 154   for (int i = 0; i < num_frames; i++) {
 155     int size = 1000 + base::RandInt(-100, 100);
 156     total_size += size;
 157     cast_environment_->Logging()->InsertEncodedFrameEvent(
 158         sender_clock_->NowTicks(),
 159         FRAME_ENCODED, VIDEO_EVENT,
 160         rtp_timestamp,
 161         frame_id,
 162         size,
 163         true,
 164         5678,
 165         9.10,
 166         11.12);
 167     last_event_time = sender_clock_->NowTicks();
 168
 169     AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 170     rtp_timestamp += 90;
 171     frame_id++;
 172   }
 173
 174   base::TimeTicks end_time = sender_clock_->NowTicks();
 175
 176   StatsEventSubscriber::StatsMap stats_map;
 177   subscriber_->GetStatsInternal(&stats_map);
 178
 179   StatsEventSubscriber::StatsMap::iterator it =
 180       stats_map.find(StatsEventSubscriber::ENCODE_FPS);
 181   ASSERT_TRUE(it != stats_map.end());
 182
 183   base::TimeDelta duration = end_time - start_time;
 184   EXPECT_DOUBLE_EQ(
 185       it->second,
 186       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 187
 188   it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
 189   ASSERT_TRUE(it != stats_map.end());
 190
 191   EXPECT_DOUBLE_EQ(it->second,
 192               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 193
 194   it = stats_map.find(StatsEventSubscriber::FIRST_EVENT_TIME_MS);
 195   ASSERT_TRUE(it != stats_map.end());
 196
 197   EXPECT_DOUBLE_EQ(
 198       it->second,
 199       (first_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
 200
 201   it = stats_map.find(StatsEventSubscriber::LAST_EVENT_TIME_MS);
 202   ASSERT_TRUE(it != stats_map.end());
 203
 204   EXPECT_DOUBLE_EQ(
 205       it->second,
 206       (last_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
 207 }
 208
 209 TEST_F(StatsEventSubscriberTest, Decode) {
 210   Init(VIDEO_EVENT);
 211
 212   uint32 rtp_timestamp = 0;
 213   uint32 frame_id = 0;
 214   int num_frames = 10;
 215   base::TimeTicks start_time = sender_clock_->NowTicks();
 216   for (int i = 0; i < num_frames; i++) {
 217     cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(),
 218                                                    FRAME_DECODED, VIDEO_EVENT,
 219                                                    rtp_timestamp,
 220                                                    frame_id);
 221
 222     AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
 223     rtp_timestamp += 90;
 224     frame_id++;
 225   }
 226
 227   base::TimeTicks end_time = sender_clock_->NowTicks();
 228
 229   StatsEventSubscriber::StatsMap stats_map;
 230   subscriber_->GetStatsInternal(&stats_map);
 231
 232   StatsEventSubscriber::StatsMap::iterator it =
 233       stats_map.find(StatsEventSubscriber::DECODE_FPS);
 234   ASSERT_TRUE(it != stats_map.end());
 235
 236   base::TimeDelta duration = end_time - start_time;
 237   EXPECT_DOUBLE_EQ(
 238       it->second,
 239       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 240 }
 241
 242 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
 243   Init(VIDEO_EVENT);
 244
 245   uint32 rtp_timestamp = 0;
 246   uint32 frame_id = 0;
 247   int num_frames = 10;
 248   int late_frames = 0;
 249   for (int i = 0, delay_ms = -50; i < num_frames; i++, delay_ms += 10) {
 250     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
 251     if (delay_ms > 0)
 252       late_frames++;
 253     cast_environment_->Logging()->InsertFrameEventWithDelay(
 254         receiver_clock_.NowTicks(),
 255         FRAME_PLAYOUT,
 256         VIDEO_EVENT,
 257         rtp_timestamp,
 258         frame_id,
 259         delay);
 260
 261     AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
 262     rtp_timestamp += 90;
 263     frame_id++;
 264   }
 265
 266   StatsEventSubscriber::StatsMap stats_map;
 267   subscriber_->GetStatsInternal(&stats_map);
 268
 269   StatsEventSubscriber::StatsMap::iterator it = stats_map.find(
 270       StatsEventSubscriber::NUM_FRAMES_LATE);
 271   ASSERT_TRUE(it != stats_map.end());
 272
 273   EXPECT_DOUBLE_EQ(it->second, late_frames);
 274 }
 275
 276 TEST_F(StatsEventSubscriberTest, E2ELatency) {
 277   Init(VIDEO_EVENT);
 278
 279   uint32 rtp_timestamp = 0;
 280   uint32 frame_id = 0;
 281   int num_frames = 10;
 282   base::TimeDelta total_latency;
 283   for (int i = 0; i < num_frames; i++) {
 284     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 285                                                    FRAME_CAPTURE_BEGIN,
 286                                                    VIDEO_EVENT,
 287                                                    rtp_timestamp,
 288                                                    frame_id);
 289
 290     int latency_micros = 100000 + base::RandInt(-5000, 50000);
 291     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 292     AdvanceClocks(latency);
 293
 294     int delay_micros = base::RandInt(-50000, 50000);
 295     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
 296     total_latency += latency;
 297
 298     cast_environment_->Logging()->InsertFrameEventWithDelay(
 299         receiver_clock_.NowTicks(),
 300         FRAME_PLAYOUT,
 301         VIDEO_EVENT,
 302         rtp_timestamp,
 303         frame_id,
 304         delay);
 305
 306     rtp_timestamp += 90;
 307     frame_id++;
 308   }
 309
 310   StatsEventSubscriber::StatsMap stats_map;
 311   subscriber_->GetStatsInternal(&stats_map);
 312
 313   StatsEventSubscriber::StatsMap::iterator it =
 314       stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
 315   ASSERT_TRUE(it != stats_map.end());
 316
 317   EXPECT_DOUBLE_EQ(
 318       it->second, total_latency.InMillisecondsF() / num_frames);
 319 }
 320
 321 TEST_F(StatsEventSubscriberTest, Packets) {
 322   Init(VIDEO_EVENT);
 323
 324   uint32 rtp_timestamp = 0;
 325   int num_packets = 10;
 326   int num_latency_recorded_packets = 0;
 327   base::TimeTicks start_time = sender_clock_->NowTicks();
 328   int total_size = 0;
 329   int retransmit_total_size = 0;
 330   base::TimeDelta total_network_latency;
 331   base::TimeDelta total_queueing_latency;
 332   base::TimeDelta total_packet_latency;
 333   int num_packets_transmitted = 0;
 334   int num_packets_received = 0;
 335   int num_packets_retransmitted = 0;
 336   int num_packets_rtx_rejected = 0;
 337
 338   base::TimeTicks sender_encoded_time = sender_clock_->NowTicks();
 339   base::TimeTicks receiver_encoded_time = receiver_clock_.NowTicks();
 340   cast_environment_->Logging()->InsertFrameEvent(sender_encoded_time,
 341                                                  FRAME_ENCODED,
 342                                                  VIDEO_EVENT,
 343                                                  rtp_timestamp,
 344                                                  0);
 345
 346   // Every 2nd packet will be retransmitted once.
 347   // Every 4th packet will be retransmitted twice.
 348   // Every 8th packet will be retransmitted 3 times + 1 rejected retransmission.
 349   for (int i = 0; i < num_packets; i++) {
 350     int size = 1000 + base::RandInt(-100, 100);
 351     total_size += size;
 352
 353     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
 354                                                     PACKET_SENT_TO_NETWORK,
 355                                                     VIDEO_EVENT,
 356                                                     rtp_timestamp,
 357                                                     0,
 358                                                     i,
 359                                                     num_packets - 1,
 360                                                     size);
 361     num_packets_transmitted++;
 362     total_queueing_latency += sender_clock_->NowTicks() - sender_encoded_time;
 363
 364     int latency_micros = 20000 + base::RandInt(-10000, 10000);
 365     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 366     // Latency is only recorded for packets that aren't retransmitted.
 367     if (i % 2 != 0) {
 368       total_network_latency += latency;
 369       total_packet_latency +=
 370           receiver_clock_.NowTicks() - receiver_encoded_time + latency;
 371       num_latency_recorded_packets++;
 372     }
 373
 374     AdvanceClocks(latency);
 375
 376     base::TimeTicks received_time = receiver_clock_.NowTicks();
 377
 378     // Retransmission 1.
 379     AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
 380     if (i % 2 == 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       retransmit_total_size += size;
 391       num_packets_transmitted++;
 392       num_packets_retransmitted++;
 393     }
 394
 395     // Retransmission 2.
 396     AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
 397     if (i % 4 == 0) {
 398       cast_environment_->Logging()->InsertPacketEvent(
 399           receiver_clock_.NowTicks(),
 400           PACKET_RETRANSMITTED,
 401           VIDEO_EVENT,
 402           rtp_timestamp,
 403           0,
 404           i,
 405           num_packets - 1,
 406           size);
 407       retransmit_total_size += size;
 408       num_packets_transmitted++;
 409       num_packets_retransmitted++;
 410     }
 411
 412     // Retransmission 3.
 413     AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
 414     if (i % 8 == 0) {
 415       cast_environment_->Logging()->InsertPacketEvent(
 416           receiver_clock_.NowTicks(),
 417           PACKET_RETRANSMITTED,
 418           VIDEO_EVENT,
 419           rtp_timestamp,
 420           0,
 421           i,
 422           num_packets - 1,
 423           size);
 424       cast_environment_->Logging()->InsertPacketEvent(
 425           receiver_clock_.NowTicks(),
 426           PACKET_RTX_REJECTED,
 427           VIDEO_EVENT,
 428           rtp_timestamp,
 429           0,
 430           i,
 431           num_packets - 1,
 432           size);
 433       retransmit_total_size += size;
 434       num_packets_transmitted++;
 435       num_packets_retransmitted++;
 436       num_packets_rtx_rejected++;
 437     }
 438
 439     cast_environment_->Logging()->InsertPacketEvent(received_time,
 440                                                     PACKET_RECEIVED,
 441                                                     VIDEO_EVENT,
 442                                                     rtp_timestamp,
 443                                                     0,
 444                                                     i,
 445                                                     num_packets - 1,
 446                                                     size);
 447     num_packets_received++;
 448   }
 449
 450   base::TimeTicks end_time = sender_clock_->NowTicks();
 451   base::TimeDelta duration = end_time - start_time;
 452
 453   StatsEventSubscriber::StatsMap stats_map;
 454   subscriber_->GetStatsInternal(&stats_map);
 455
 456   // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS.
 457   StatsEventSubscriber::StatsMap::iterator it =
 458       stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
 459   ASSERT_TRUE(it != stats_map.end());
 460
 461   EXPECT_DOUBLE_EQ(
 462       it->second,
 463       total_network_latency.InMillisecondsF() / num_latency_recorded_packets);
 464
 465   it = stats_map.find(StatsEventSubscriber::AVG_QUEUEING_LATENCY_MS);
 466   ASSERT_TRUE(it != stats_map.end());
 467
 468   EXPECT_DOUBLE_EQ(
 469       it->second,
 470       total_queueing_latency.InMillisecondsF() / num_packets);
 471
 472   it = stats_map.find(StatsEventSubscriber::AVG_PACKET_LATENCY_MS);
 473   ASSERT_TRUE(it != stats_map.end());
 474
 475   EXPECT_DOUBLE_EQ(
 476       it->second,
 477       total_packet_latency.InMillisecondsF() / num_latency_recorded_packets);
 478
 479   it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
 480   ASSERT_TRUE(it != stats_map.end());
 481
 482   EXPECT_DOUBLE_EQ(it->second,
 483               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 484
 485   it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
 486   ASSERT_TRUE(it != stats_map.end());
 487
 488   EXPECT_DOUBLE_EQ(it->second,
 489               static_cast<double>(retransmit_total_size) /
 490                   duration.InMillisecondsF() * 8);
 491
 492   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_SENT);
 493   ASSERT_TRUE(it != stats_map.end());
 494
 495   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets));
 496
 497   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RECEIVED);
 498   ASSERT_TRUE(it != stats_map.end());
 499
 500   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_received));
 501
 502   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RETRANSMITTED);
 503   ASSERT_TRUE(it != stats_map.end());
 504
 505   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_retransmitted));
 506
 507   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RTX_REJECTED);
 508   ASSERT_TRUE(it != stats_map.end());
 509
 510   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_rtx_rejected));
 511 }
 512
 513 bool CheckHistogramHasValue(base::ListValue* values,
 514                             const std::string& bucket, int expected_count) {
 515   for (size_t i = 0; i < values->GetSize(); ++i) {
 516     const base::DictionaryValue* dict = NULL;
 517     values->GetDictionary(i, &dict);
 518     if (!dict->HasKey(bucket))
 519       continue;
 520     int bucket_count = 0;
 521     if (!dict->GetInteger(bucket, &bucket_count))
 522       return false;
 523     return bucket_count == expected_count;
 524   }
 525   return false;
 526 }
 527
 528 TEST_F(StatsEventSubscriberTest, Histograms) {
 529   Init(VIDEO_EVENT);
 530   AdvanceClocks(base::TimeDelta::FromMilliseconds(123));
 531
 532   uint32 rtp_timestamp = 123;
 533   uint32 frame_id = 0;
 534
 535   // 10 Frames with capture latency in the bucket of "10-14"ms.
 536   // 10 Frames with encode time in the bucket of "15-19"ms.
 537   for (int i = 0; i < 10; ++i) {
 538     ++frame_id;
 539     ++rtp_timestamp;
 540     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 541                                                    FRAME_CAPTURE_BEGIN,
 542                                                    VIDEO_EVENT,
 543                                                    rtp_timestamp,
 544                                                    frame_id);
 545     AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
 546     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 547                                                    FRAME_CAPTURE_END,
 548                                                    VIDEO_EVENT,
 549                                                    rtp_timestamp,
 550                                                    frame_id);
 551     AdvanceClocks(base::TimeDelta::FromMilliseconds(15));
 552     cast_environment_->Logging()->InsertEncodedFrameEvent(
 553         sender_clock_->NowTicks(),
 554         FRAME_ENCODED,
 555         VIDEO_EVENT,
 556         rtp_timestamp,
 557         frame_id,
 558         1024,
 559         true,
 560         5678,
 561         9.10,
 562         11.12);
 563   }
 564
 565   // Send 3 packets for the last frame.
 566   // Queueing latencies are 100ms, 200ms and 300ms.
 567   for (int i = 0; i < 3; ++i) {
 568     AdvanceClocks(base::TimeDelta::FromMilliseconds(100));
 569     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
 570                                                     PACKET_SENT_TO_NETWORK,
 571                                                     VIDEO_EVENT,
 572                                                     rtp_timestamp,
 573                                                     0,
 574                                                     i,
 575                                                     2,
 576                                                     123);
 577   }
 578
 579   // Receive 3 packets for the last frame.
 580   // Network latencies are 100ms, 200ms and 300ms.
 581   // Packet latencies are 400ms.
 582   AdvanceClocks(base::TimeDelta::FromMilliseconds(100));
 583   for (int i = 0; i < 3; ++i) {
 584     cast_environment_->Logging()->InsertPacketEvent(receiver_clock_.NowTicks(),
 585                                                     PACKET_RECEIVED,
 586                                                     VIDEO_EVENT,
 587                                                     rtp_timestamp,
 588                                                     0,
 589                                                     i,
 590                                                     2,
 591                                                     123);
 592   }
 593
 594   cast_environment_->Logging()->InsertFrameEventWithDelay(
 595       receiver_clock_.NowTicks(),
 596       FRAME_PLAYOUT,
 597       VIDEO_EVENT,
 598       rtp_timestamp,
 599       frame_id,
 600       base::TimeDelta::FromMilliseconds(100));
 601
 602   StatsEventSubscriber::SimpleHistogram* histogram;
 603   scoped_ptr<base::ListValue> values;
 604
 605   histogram = subscriber_->GetHistogramForTesting(
 606       StatsEventSubscriber::CAPTURE_LATENCY_MS_HISTO);
 607   ASSERT_TRUE(histogram);
 608   values = histogram->GetHistogram().Pass();
 609   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "10-14", 10));
 610
 611   histogram = subscriber_->GetHistogramForTesting(
 612       StatsEventSubscriber::ENCODE_TIME_MS_HISTO);
 613   ASSERT_TRUE(histogram);
 614   values = histogram->GetHistogram().Pass();
 615   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "15-19", 10));
 616
 617   histogram = subscriber_->GetHistogramForTesting(
 618       StatsEventSubscriber::QUEUEING_LATENCY_MS_HISTO);
 619   ASSERT_TRUE(histogram);
 620   values = histogram->GetHistogram().Pass();
 621   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
 622   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "200-219", 1));
 623   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "300-319", 1));
 624
 625   histogram = subscriber_->GetHistogramForTesting(
 626       StatsEventSubscriber::NETWORK_LATENCY_MS_HISTO);
 627   ASSERT_TRUE(histogram);
 628   values = histogram->GetHistogram().Pass();
 629   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
 630   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "200-219", 1));
 631   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "300-319", 1));
 632
 633   histogram = subscriber_->GetHistogramForTesting(
 634       StatsEventSubscriber::PACKET_LATENCY_MS_HISTO);
 635   ASSERT_TRUE(histogram);
 636   values = histogram->GetHistogram().Pass();
 637   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "400-419", 3));
 638
 639   histogram = subscriber_->GetHistogramForTesting(
 640       StatsEventSubscriber::LATE_FRAME_MS_HISTO);
 641   ASSERT_TRUE(histogram);
 642   values = histogram->GetHistogram().Pass();
 643   EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
 644 }
 645
 646 }  // namespace cast
 647 }  // namespace media