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   AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 144   base::TimeTicks first_event_time = sender_clock_->NowTicks();
 145   base::TimeTicks last_event_time;
 146   int total_size = 0;
 147   for (int i = 0; i < num_frames; i++) {
 148     int size = 1000 + base::RandInt(-100, 100);
 149     total_size += size;
 150     cast_environment_->Logging()->InsertEncodedFrameEvent(
 151         sender_clock_->NowTicks(),
 152         FRAME_ENCODED, VIDEO_EVENT,
 153         rtp_timestamp,
 154         frame_id,
 155         size,
 156         true,
 157         5678);
 158     last_event_time = sender_clock_->NowTicks();
 159
 160     AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
 161     rtp_timestamp += 90;
 162     frame_id++;
 163   }
 164
 165   base::TimeTicks end_time = sender_clock_->NowTicks();
 166
 167   StatsEventSubscriber::StatsMap stats_map;
 168   subscriber_->GetStatsInternal(&stats_map);
 169
 170   StatsEventSubscriber::StatsMap::iterator it =
 171       stats_map.find(StatsEventSubscriber::ENCODE_FPS);
 172   ASSERT_TRUE(it != stats_map.end());
 173
 174   base::TimeDelta duration = end_time - start_time;
 175   EXPECT_DOUBLE_EQ(
 176       it->second,
 177       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 178
 179   it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
 180   ASSERT_TRUE(it != stats_map.end());
 181
 182   EXPECT_DOUBLE_EQ(it->second,
 183               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 184
 185   it = stats_map.find(StatsEventSubscriber::FIRST_EVENT_TIME_MS);
 186   ASSERT_TRUE(it != stats_map.end());
 187
 188   EXPECT_DOUBLE_EQ(
 189       it->second,
 190       (first_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
 191
 192   it = stats_map.find(StatsEventSubscriber::LAST_EVENT_TIME_MS);
 193   ASSERT_TRUE(it != stats_map.end());
 194
 195   EXPECT_DOUBLE_EQ(
 196       it->second,
 197       (last_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
 198 }
 199
 200 TEST_F(StatsEventSubscriberTest, Decode) {
 201   Init(VIDEO_EVENT);
 202
 203   uint32 rtp_timestamp = 0;
 204   uint32 frame_id = 0;
 205   int num_frames = 10;
 206   base::TimeTicks start_time = sender_clock_->NowTicks();
 207   for (int i = 0; i < num_frames; i++) {
 208     cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(),
 209                                                    FRAME_DECODED, VIDEO_EVENT,
 210                                                    rtp_timestamp,
 211                                                    frame_id);
 212
 213     AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
 214     rtp_timestamp += 90;
 215     frame_id++;
 216   }
 217
 218   base::TimeTicks end_time = sender_clock_->NowTicks();
 219
 220   StatsEventSubscriber::StatsMap stats_map;
 221   subscriber_->GetStatsInternal(&stats_map);
 222
 223   StatsEventSubscriber::StatsMap::iterator it =
 224       stats_map.find(StatsEventSubscriber::DECODE_FPS);
 225   ASSERT_TRUE(it != stats_map.end());
 226
 227   base::TimeDelta duration = end_time - start_time;
 228   EXPECT_DOUBLE_EQ(
 229       it->second,
 230       static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
 231 }
 232
 233 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
 234   Init(VIDEO_EVENT);
 235
 236   uint32 rtp_timestamp = 0;
 237   uint32 frame_id = 0;
 238   int num_frames = 10;
 239   int total_delay_ms = 0;
 240   int late_frames = 0;
 241   for (int i = 0, delay_ms = -50; i < num_frames; i++, delay_ms += 10) {
 242     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
 243     total_delay_ms += delay_ms;
 244     if (delay_ms <= 0)
 245       late_frames++;
 246     cast_environment_->Logging()->InsertFrameEventWithDelay(
 247         receiver_clock_.NowTicks(),
 248         FRAME_PLAYOUT,
 249         VIDEO_EVENT,
 250         rtp_timestamp,
 251         frame_id,
 252         delay);
 253
 254     AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
 255     rtp_timestamp += 90;
 256     frame_id++;
 257   }
 258
 259   StatsEventSubscriber::StatsMap stats_map;
 260   subscriber_->GetStatsInternal(&stats_map);
 261
 262   StatsEventSubscriber::StatsMap::iterator it =
 263       stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS);
 264   ASSERT_TRUE(it != stats_map.end());
 265
 266   EXPECT_DOUBLE_EQ(
 267       it->second, static_cast<double>(total_delay_ms) / num_frames);
 268
 269   it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_LATE);
 270   ASSERT_TRUE(it != stats_map.end());
 271
 272   EXPECT_DOUBLE_EQ(it->second, late_frames);
 273 }
 274
 275 TEST_F(StatsEventSubscriberTest, E2ELatency) {
 276   Init(VIDEO_EVENT);
 277
 278   uint32 rtp_timestamp = 0;
 279   uint32 frame_id = 0;
 280   int num_frames = 10;
 281   base::TimeDelta total_latency;
 282   for (int i = 0; i < num_frames; i++) {
 283     cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(),
 284                                                    FRAME_CAPTURE_BEGIN,
 285                                                    VIDEO_EVENT,
 286                                                    rtp_timestamp,
 287                                                    frame_id);
 288
 289     int latency_micros = 100000 + base::RandInt(-5000, 50000);
 290     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 291     AdvanceClocks(latency);
 292
 293     int delay_micros = base::RandInt(-50000, 50000);
 294     base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
 295     total_latency += latency + delay;
 296
 297     cast_environment_->Logging()->InsertFrameEventWithDelay(
 298         receiver_clock_.NowTicks(),
 299         FRAME_PLAYOUT,
 300         VIDEO_EVENT,
 301         rtp_timestamp,
 302         frame_id,
 303         delay);
 304
 305     rtp_timestamp += 90;
 306     frame_id++;
 307   }
 308
 309   StatsEventSubscriber::StatsMap stats_map;
 310   subscriber_->GetStatsInternal(&stats_map);
 311
 312   StatsEventSubscriber::StatsMap::iterator it =
 313       stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
 314   ASSERT_TRUE(it != stats_map.end());
 315
 316   EXPECT_DOUBLE_EQ(
 317       it->second, total_latency.InMillisecondsF() / num_frames);
 318 }
 319
 320 TEST_F(StatsEventSubscriberTest, Packets) {
 321   Init(VIDEO_EVENT);
 322
 323   uint32 rtp_timestamp = 0;
 324   int num_packets = 10;
 325   int num_latency_recorded_packets = 0;
 326   base::TimeTicks start_time = sender_clock_->NowTicks();
 327   int total_size = 0;
 328   int retransmit_total_size = 0;
 329   base::TimeDelta total_latency;
 330   int num_packets_transmitted = 0;
 331   int num_packets_retransmitted = 0;
 332   int num_packets_rtx_rejected = 0;
 333   // Every 2nd packet will be retransmitted once.
 334   // Every 4th packet will be retransmitted twice.
 335   // Every 8th packet will be retransmitted 3 times + 1 rejected retransmission.
 336   for (int i = 0; i < num_packets; i++) {
 337     int size = 1000 + base::RandInt(-100, 100);
 338     total_size += size;
 339
 340     cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(),
 341                                                     PACKET_SENT_TO_NETWORK,
 342                                                     VIDEO_EVENT,
 343                                                     rtp_timestamp,
 344                                                     0,
 345                                                     i,
 346                                                     num_packets - 1,
 347                                                     size);
 348     num_packets_transmitted++;
 349
 350     int latency_micros = 20000 + base::RandInt(-10000, 10000);
 351     base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
 352     // Latency is only recorded for packets that aren't retransmitted.
 353     if (i % 2 != 0) {
 354       total_latency += latency;
 355       num_latency_recorded_packets++;
 356     }
 357
 358     AdvanceClocks(latency);
 359
 360     base::TimeTicks received_time = receiver_clock_.NowTicks();
 361
 362     // Retransmission 1.
 363     AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
 364     if (i % 2 == 0) {
 365       cast_environment_->Logging()->InsertPacketEvent(
 366           receiver_clock_.NowTicks(),
 367           PACKET_RETRANSMITTED,
 368           VIDEO_EVENT,
 369           rtp_timestamp,
 370           0,
 371           i,
 372           num_packets - 1,
 373           size);
 374       retransmit_total_size += size;
 375       num_packets_transmitted++;
 376       num_packets_retransmitted++;
 377     }
 378
 379     // Retransmission 2.
 380     AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
 381     if (i % 4 == 0) {
 382       cast_environment_->Logging()->InsertPacketEvent(
 383           receiver_clock_.NowTicks(),
 384           PACKET_RETRANSMITTED,
 385           VIDEO_EVENT,
 386           rtp_timestamp,
 387           0,
 388           i,
 389           num_packets - 1,
 390           size);
 391       retransmit_total_size += size;
 392       num_packets_transmitted++;
 393       num_packets_retransmitted++;
 394     }
 395
 396     // Retransmission 3.
 397     AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
 398     if (i % 8 == 0) {
 399       cast_environment_->Logging()->InsertPacketEvent(
 400           receiver_clock_.NowTicks(),
 401           PACKET_RETRANSMITTED,
 402           VIDEO_EVENT,
 403           rtp_timestamp,
 404           0,
 405           i,
 406           num_packets - 1,
 407           size);
 408       cast_environment_->Logging()->InsertPacketEvent(
 409           receiver_clock_.NowTicks(),
 410           PACKET_RTX_REJECTED,
 411           VIDEO_EVENT,
 412           rtp_timestamp,
 413           0,
 414           i,
 415           num_packets - 1,
 416           size);
 417       retransmit_total_size += size;
 418       num_packets_transmitted++;
 419       num_packets_retransmitted++;
 420       num_packets_rtx_rejected++;
 421     }
 422
 423     cast_environment_->Logging()->InsertPacketEvent(received_time,
 424                                                     PACKET_RECEIVED,
 425                                                     VIDEO_EVENT,
 426                                                     rtp_timestamp,
 427                                                     0,
 428                                                     i,
 429                                                     num_packets - 1,
 430                                                     size);
 431   }
 432
 433   base::TimeTicks end_time = sender_clock_->NowTicks();
 434   base::TimeDelta duration = end_time - start_time;
 435
 436   StatsEventSubscriber::StatsMap stats_map;
 437   subscriber_->GetStatsInternal(&stats_map);
 438
 439   // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS,
 440   // and PACKET_LOSS_FRACTION.
 441   StatsEventSubscriber::StatsMap::iterator it =
 442       stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
 443   ASSERT_TRUE(it != stats_map.end());
 444
 445   EXPECT_DOUBLE_EQ(
 446       it->second,
 447       total_latency.InMillisecondsF() / num_latency_recorded_packets);
 448
 449   it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
 450   ASSERT_TRUE(it != stats_map.end());
 451
 452   EXPECT_DOUBLE_EQ(it->second,
 453               static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
 454
 455   it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
 456   ASSERT_TRUE(it != stats_map.end());
 457
 458   EXPECT_DOUBLE_EQ(it->second,
 459               static_cast<double>(retransmit_total_size) /
 460                   duration.InMillisecondsF() * 8);
 461
 462   it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION);
 463   ASSERT_TRUE(it != stats_map.end());
 464
 465   EXPECT_DOUBLE_EQ(
 466       it->second,
 467       static_cast<double>(num_packets_retransmitted) / num_packets_transmitted);
 468
 469   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_SENT);
 470   ASSERT_TRUE(it != stats_map.end());
 471
 472   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets));
 473
 474   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RETRANSMITTED);
 475   ASSERT_TRUE(it != stats_map.end());
 476
 477   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_retransmitted));
 478
 479   it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RTX_REJECTED);
 480   ASSERT_TRUE(it != stats_map.end());
 481
 482   EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_rtx_rejected));
 483 }
 484
 485 }  // namespace cast
 486 }  // namespace media