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