media/cast/logging/logging_impl_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 <vector>
   6
   7 #include "base/rand_util.h"
   8 #include "base/test/simple_test_tick_clock.h"
   9 #include "base/time/tick_clock.h"
  10 #include "base/time/time.h"
  11 #include "media/cast/logging/logging_defines.h"
  12 #include "media/cast/logging/logging_impl.h"
  13 #include "media/cast/logging/simple_event_subscriber.h"
  14 #include "media/cast/test/fake_single_thread_task_runner.h"
  15 #include "testing/gtest/include/gtest/gtest.h"
  16
  17 namespace media {
  18 namespace cast {
  19
  20 // Insert frame duration- one second.
  21 const int64 kIntervalTime1S = 1;
  22 // Test frame rate goal - 30fps.
  23 const int kFrameIntervalMs = 33;
  24
  25 static const int64 kStartMillisecond = GG_INT64_C(12345678900000);
  26
  27 class LoggingImplTest : public ::testing::Test {
  28  protected:
  29   LoggingImplTest() {
  30     // Enable all logging types.
  31     config_.enable_raw_data_collection = true;
  32     config_.enable_stats_data_collection = true;
  33     config_.enable_tracing = true;
  34
  35     testing_clock_.Advance(
  36         base::TimeDelta::FromMilliseconds(kStartMillisecond));
  37     task_runner_ = new test::FakeSingleThreadTaskRunner(&testing_clock_);
  38     logging_.reset(new LoggingImpl(task_runner_, config_));
  39     logging_->AddRawEventSubscriber(&event_subscriber_);
  40   }
  41
  42   virtual ~LoggingImplTest() {
  43     logging_->RemoveRawEventSubscriber(&event_subscriber_);
  44   }
  45
  46   CastLoggingConfig config_;
  47   scoped_refptr<test::FakeSingleThreadTaskRunner> task_runner_;
  48   scoped_ptr<LoggingImpl> logging_;
  49   base::SimpleTestTickClock testing_clock_;
  50   SimpleEventSubscriber event_subscriber_;
  51
  52   DISALLOW_COPY_AND_ASSIGN(LoggingImplTest);
  53 };
  54
  55 TEST_F(LoggingImplTest, BasicFrameLogging) {
  56   base::TimeTicks start_time = testing_clock_.NowTicks();
  57   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
  58   uint32 rtp_timestamp = 0;
  59   uint32 frame_id = 0;
  60   base::TimeTicks now;
  61   do {
  62     now = testing_clock_.NowTicks();
  63     logging_->InsertFrameEvent(now, kAudioFrameCaptured, rtp_timestamp,
  64                                frame_id);
  65     testing_clock_.Advance(
  66         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
  67     rtp_timestamp += kFrameIntervalMs * 90;
  68     ++frame_id;
  69     time_interval = now - start_time;
  70   }  while (time_interval.InSeconds() < kIntervalTime1S);
  71   base::TimeTicks end_time = now;
  72
  73   // Get logging data.
  74   std::vector<FrameEvent> frame_events;
  75   event_subscriber_.GetFrameEventsAndReset(&frame_events);
  76   // Size of vector should be equal to the number of events logged,
  77   // which equals to number of frames in this case.
  78   EXPECT_EQ(frame_id, frame_events.size());
  79   // Verify stats.
  80   FrameStatsMap frame_stats = logging_->GetFrameStatsData();
  81   // Size of stats equals the number of events.
  82   EXPECT_EQ(1u, frame_stats.size());
  83   FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured);
  84   EXPECT_TRUE(it != frame_stats.end());
  85   EXPECT_EQ(0, it->second.max_delay.InMilliseconds());
  86   EXPECT_EQ(0, it->second.min_delay.InMilliseconds());
  87   EXPECT_EQ(start_time, it->second.first_event_time);
  88   EXPECT_EQ(end_time, it->second.last_event_time);
  89   EXPECT_EQ(0u, it->second.sum_size);
  90   // Number of events is equal to the number of frames.
  91   EXPECT_EQ(static_cast<int>(frame_id), it->second.event_counter);
  92 }
  93
  94 TEST_F(LoggingImplTest, FrameLoggingWithSize) {
  95   // Average packet size.
  96   const int kBaseFrameSizeBytes = 25000;
  97   const int kRandomSizeInterval = 100;
  98   base::TimeTicks start_time = testing_clock_.NowTicks();
  99   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 100   uint32 rtp_timestamp = 0;
 101   uint32 frame_id = 0;
 102   size_t sum_size = 0;
 103   do {
 104     int size = kBaseFrameSizeBytes +
 105         base::RandInt(-kRandomSizeInterval, kRandomSizeInterval);
 106     sum_size += static_cast<size_t>(size);
 107     logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(),
 108                                        kAudioFrameCaptured, rtp_timestamp,
 109                                        frame_id, size);
 110     testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 111     rtp_timestamp += kFrameIntervalMs * 90;
 112     ++frame_id;
 113     time_interval = testing_clock_.NowTicks() - start_time;
 114   } while (time_interval.InSeconds() < kIntervalTime1S);
 115   // Get logging data.
 116   std::vector<FrameEvent> frame_events;
 117   event_subscriber_.GetFrameEventsAndReset(&frame_events);
 118   // Size of vector should be equal to the number of events logged, which
 119   // equals to number of frames in this case.
 120   EXPECT_EQ(frame_id, frame_events.size());
 121   // Verify stats.
 122   FrameStatsMap frame_stats = logging_->GetFrameStatsData();
 123   // Size of stats equals the number of events.
 124   EXPECT_EQ(1u, frame_stats.size());
 125   FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured);
 126   EXPECT_TRUE(it != frame_stats.end());
 127   EXPECT_EQ(0, it->second.max_delay.InMilliseconds());
 128   EXPECT_EQ(0, it->second.min_delay.InMilliseconds());
 129   EXPECT_EQ(0, it->second.sum_delay.InMilliseconds());
 130   EXPECT_EQ(sum_size, it->second.sum_size);
 131 }
 132
 133 TEST_F(LoggingImplTest, FrameLoggingWithDelay) {
 134   // Average packet size.
 135   const int kPlayoutDelayMs = 50;
 136   const int kRandomSizeInterval = 20;
 137   base::TimeTicks start_time = testing_clock_.NowTicks();
 138   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 139   uint32 rtp_timestamp = 0;
 140   uint32 frame_id = 0;
 141   do {
 142     int delay = kPlayoutDelayMs +
 143                 base::RandInt(-kRandomSizeInterval, kRandomSizeInterval);
 144     logging_->InsertFrameEventWithDelay(
 145         testing_clock_.NowTicks(), kAudioFrameCaptured, rtp_timestamp, frame_id,
 146         base::TimeDelta::FromMilliseconds(delay));
 147     testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 148     rtp_timestamp += kFrameIntervalMs * 90;
 149     ++frame_id;
 150     time_interval = testing_clock_.NowTicks() - start_time;
 151   } while (time_interval.InSeconds() < kIntervalTime1S);
 152   // Get logging data.
 153   std::vector<FrameEvent> frame_events;
 154   event_subscriber_.GetFrameEventsAndReset(&frame_events);
 155   // Size of vector should be equal to the number of frames logged.
 156   EXPECT_EQ(frame_id, frame_events.size());
 157   // Verify stats.
 158   FrameStatsMap frame_stats = logging_->GetFrameStatsData();
 159   // Size of stats equals the number of events.
 160   EXPECT_EQ(1u, frame_stats.size());
 161   FrameStatsMap::const_iterator it = frame_stats.find(kAudioFrameCaptured);
 162   EXPECT_TRUE(it != frame_stats.end());
 163   EXPECT_GE(kPlayoutDelayMs + kRandomSizeInterval,
 164       it->second.max_delay.InMilliseconds());
 165   EXPECT_LE(kPlayoutDelayMs - kRandomSizeInterval,
 166       it->second.min_delay.InMilliseconds());
 167 }
 168
 169 TEST_F(LoggingImplTest, MultipleEventFrameLogging) {
 170   base::TimeTicks start_time = testing_clock_.NowTicks();
 171   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 172   uint32 rtp_timestamp = 0u;
 173   uint32 frame_id = 0u;
 174   uint32 num_events = 0u;
 175   do {
 176     logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured,
 177                                rtp_timestamp, frame_id);
 178     ++num_events;
 179     if (frame_id % 2) {
 180       logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(),
 181                                          kAudioFrameEncoded, rtp_timestamp,
 182                                          frame_id, 1500);
 183     } else if (frame_id % 3) {
 184       logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded,
 185                                  rtp_timestamp, frame_id);
 186     } else {
 187       logging_->InsertFrameEventWithDelay(
 188           testing_clock_.NowTicks(), kVideoRenderDelay, rtp_timestamp, frame_id,
 189           base::TimeDelta::FromMilliseconds(20));
 190     }
 191     ++num_events;
 192
 193     testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 194     rtp_timestamp += kFrameIntervalMs * 90;
 195     ++frame_id;
 196     time_interval = testing_clock_.NowTicks() - start_time;
 197   } while (time_interval.InSeconds() < kIntervalTime1S);
 198   // Get logging data.
 199   std::vector<FrameEvent> frame_events;
 200   event_subscriber_.GetFrameEventsAndReset(&frame_events);
 201   // Size of vector should be equal to the number of frames logged.
 202   EXPECT_EQ(num_events, frame_events.size());
 203   // Multiple events captured per frame.
 204 }
 205
 206 TEST_F(LoggingImplTest, PacketLogging) {
 207   const int kNumPacketsPerFrame = 10;
 208   const int kBaseSize = 2500;
 209   const int kSizeInterval = 100;
 210   base::TimeTicks start_time = testing_clock_.NowTicks();
 211   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 212   uint32 rtp_timestamp = 0;
 213   uint32 frame_id = 0;
 214   do {
 215     for (int i = 0; i < kNumPacketsPerFrame; ++i) {
 216       int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval);
 217       logging_->InsertPacketEvent(testing_clock_.NowTicks(), kPacketSentToPacer,
 218                                   rtp_timestamp, frame_id, i,
 219                                   kNumPacketsPerFrame, size);
 220     }
 221     testing_clock_.Advance(base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 222     rtp_timestamp += kFrameIntervalMs * 90;
 223     ++frame_id;
 224     time_interval = testing_clock_.NowTicks() - start_time;
 225   } while (time_interval.InSeconds() < kIntervalTime1S);
 226   // Get logging data.
 227   std::vector<PacketEvent> packet_events;
 228   event_subscriber_.GetPacketEventsAndReset(&packet_events);
 229   // Size of vector should be equal to the number of packets logged.
 230   EXPECT_EQ(frame_id * kNumPacketsPerFrame, packet_events.size());
 231   // Verify stats.
 232   PacketStatsMap stats_map = logging_->GetPacketStatsData();
 233   // Size of stats equals the number of events.
 234   EXPECT_EQ(1u, stats_map.size());
 235   PacketStatsMap::const_iterator it = stats_map.find(kPacketSentToPacer);
 236   EXPECT_TRUE(it != stats_map.end());
 237 }
 238
 239 TEST_F(LoggingImplTest, GenericLogging) {
 240   // Insert multiple generic types.
 241   const size_t kNumRuns = 20;//1000;
 242   const int kBaseValue = 20;
 243   int sum_value_rtt = 0;
 244   int sum_value_pl = 0;
 245   int sum_value_jitter = 0;
 246   uint64 sumsq_value_rtt = 0;
 247   uint64 sumsq_value_pl = 0;
 248   uint64 sumsq_value_jitter = 0;
 249   int min_value, max_value;
 250
 251   uint32 num_events = 0u;
 252   uint32 expected_rtt_count = 0u;
 253   uint32 expected_packet_loss_count = 0u;
 254   uint32 expected_jitter_count = 0u;
 255   for (size_t i = 0; i < kNumRuns; ++i) {
 256     int value = kBaseValue + base::RandInt(-5, 5);
 257     sum_value_rtt += value;
 258     sumsq_value_rtt += value * value;
 259     logging_->InsertGenericEvent(testing_clock_.NowTicks(), kRttMs, value);
 260     ++num_events;
 261     ++expected_rtt_count;
 262     if (i % 2) {
 263       logging_->InsertGenericEvent(testing_clock_.NowTicks(), kPacketLoss,
 264                                    value);
 265       ++num_events;
 266       ++expected_packet_loss_count;
 267       sum_value_pl += value;
 268       sumsq_value_pl += value * value;
 269     }
 270     if (!(i % 4)) {
 271       logging_->InsertGenericEvent(testing_clock_.NowTicks(), kJitterMs, value);
 272       ++num_events;
 273       ++expected_jitter_count;
 274       sum_value_jitter += value;
 275       sumsq_value_jitter += value * value;
 276     }
 277     if (i == 0) {
 278       min_value = value;
 279       max_value = value;
 280     } else if (min_value > value) {
 281       min_value = value;
 282     } else if (max_value < value) {
 283       max_value = value;
 284     }
 285   }
 286
 287   // Size of generic event vector = number of generic events logged.
 288   std::vector<GenericEvent> generic_events;
 289   event_subscriber_.GetGenericEventsAndReset(&generic_events);
 290   EXPECT_EQ(num_events, generic_events.size());
 291
 292   // Verify each type of event has expected number of events logged.
 293   uint32 rtt_event_count = 0u;
 294   uint32 packet_loss_event_count = 0u;
 295   uint32 jitter_event_count = 0u;
 296   for (std::vector<GenericEvent>::iterator it = generic_events.begin();
 297        it != generic_events.end(); ++it) {
 298     if (it->type == kRttMs) {
 299       ++rtt_event_count;
 300     } else if (it->type == kPacketLoss) {
 301       ++packet_loss_event_count;
 302     } else if (it->type == kJitterMs) {
 303       ++jitter_event_count;
 304     }
 305   }
 306
 307   // Size of generic stats map = number of different events.
 308   // Stats - one value per all events.
 309   GenericStatsMap stats_map = logging_->GetGenericStatsData();
 310   EXPECT_EQ(3u, stats_map.size());
 311   GenericStatsMap::const_iterator sit = stats_map.find(kRttMs);
 312   EXPECT_EQ(sum_value_rtt, sit->second.sum);
 313   EXPECT_EQ(sumsq_value_rtt, sit->second.sum_squared);
 314   EXPECT_LE(min_value, sit->second.min);
 315   EXPECT_GE(max_value, sit->second.max);
 316   sit = stats_map.find(kPacketLoss);
 317   EXPECT_EQ(sum_value_pl, sit->second.sum);
 318   EXPECT_EQ(sumsq_value_pl, sit->second.sum_squared);
 319   EXPECT_LE(min_value, sit->second.min);
 320   EXPECT_GE(max_value, sit->second.max);
 321   sit = stats_map.find(kJitterMs);
 322   EXPECT_EQ(sumsq_value_jitter, sit->second.sum_squared);
 323   EXPECT_LE(min_value, sit->second.min);
 324   EXPECT_GE(max_value, sit->second.max);
 325 }
 326
 327 TEST_F(LoggingImplTest, MultipleRawEventSubscribers) {
 328   SimpleEventSubscriber event_subscriber_2;
 329
 330   // Now logging_ has two subscribers.
 331   logging_->AddRawEventSubscriber(&event_subscriber_2);
 332
 333   logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured,
 334                              /*rtp_timestamp*/ 0u,
 335                              /*frame_id*/ 0u);
 336
 337   std::vector<FrameEvent> frame_events;
 338   event_subscriber_.GetFrameEventsAndReset(&frame_events);
 339   EXPECT_EQ(1u, frame_events.size());
 340   frame_events.clear();
 341   event_subscriber_2.GetFrameEventsAndReset(&frame_events);
 342   EXPECT_EQ(1u, frame_events.size());
 343
 344   logging_->RemoveRawEventSubscriber(&event_subscriber_2);
 345 }
 346
 347 }  // namespace cast
 348 }  // namespace media