src/media/cast/logging/logging_unittest.cc

   1 // Copyright 2013 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 <gtest/gtest.h>
   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_impl.h"
  12 #include "media/cast/test/fake_task_runner.h"
  13
  14 namespace media {
  15 namespace cast {
  16
  17 // Insert frame duration- one second.
  18 const int64 kIntervalTime1S = 1;
  19 // Test frame rate goal - 30fps.
  20 const int kFrameIntervalMs = 33;
  21
  22 static const int64 kStartMillisecond = GG_INT64_C(12345678900000);
  23
  24 class TestLogging : public ::testing::Test {
  25  protected:
  26   TestLogging() : config_(false) {
  27     // Enable all logging types.
  28     config_.enable_raw_data_collection = true;
  29     config_.enable_stats_data_collection = true;
  30     config_.enable_uma_stats = true;
  31     config_.enable_tracing = true;
  32
  33     testing_clock_.Advance(
  34         base::TimeDelta::FromMilliseconds(kStartMillisecond));
  35     task_runner_ = new test::FakeTaskRunner(&testing_clock_);
  36     logging_.reset(new LoggingImpl(task_runner_, config_));
  37   }
  38
  39   virtual ~TestLogging() {}
  40
  41   CastLoggingConfig config_;
  42   scoped_refptr<test::FakeTaskRunner> task_runner_;
  43   scoped_ptr<LoggingImpl> logging_;
  44   base::SimpleTestTickClock testing_clock_;
  45 };
  46
  47 TEST_F(TestLogging, BasicFrameLogging) {
  48   base::TimeTicks start_time = testing_clock_.NowTicks();
  49   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
  50   uint32 rtp_timestamp = 0;
  51   uint32 frame_id = 0;
  52   do {
  53     logging_->InsertFrameEvent(testing_clock_.NowTicks(),
  54                                kAudioFrameCaptured, rtp_timestamp, frame_id);
  55     testing_clock_.Advance(
  56         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
  57     rtp_timestamp += kFrameIntervalMs * 90;
  58     ++frame_id;
  59     time_interval = testing_clock_.NowTicks() - start_time;
  60   }  while (time_interval.InSeconds() < kIntervalTime1S);
  61   // Get logging data.
  62   FrameRawMap frame_map = logging_->GetFrameRawData();
  63   // Size of map should be equal to the number of frames logged.
  64   EXPECT_EQ(frame_id, frame_map.size());
  65   // Verify stats.
  66   const FrameStatsMap* frame_stats =
  67       logging_->GetFrameStatsData(testing_clock_.NowTicks());
  68   // Size of stats equals the number of events.
  69   EXPECT_EQ(1u, frame_stats->size());
  70   FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured);
  71   EXPECT_TRUE(it != frame_stats->end());
  72   EXPECT_NEAR(30.3, it->second->framerate_fps, 0.1);
  73   EXPECT_EQ(0, it->second->bitrate_kbps);
  74   EXPECT_EQ(0, it->second->max_delay_ms);
  75   EXPECT_EQ(0, it->second->min_delay_ms);
  76   EXPECT_EQ(0, it->second->avg_delay_ms);
  77 }
  78
  79 TEST_F(TestLogging, FrameLoggingWithSize) {
  80   // Average packet size.
  81   const int kBaseFrameSizeBytes = 25000;
  82   const int kRandomSizeInterval = 100;
  83   base::TimeTicks start_time = testing_clock_.NowTicks();
  84   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
  85   uint32 rtp_timestamp = 0;
  86   uint32 frame_id = 0;
  87   do {
  88     int size = kBaseFrameSizeBytes +
  89         base::RandInt(-kRandomSizeInterval, kRandomSizeInterval);
  90     logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(),
  91         kAudioFrameCaptured, rtp_timestamp, frame_id, size);
  92     testing_clock_.Advance(
  93         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
  94     rtp_timestamp += kFrameIntervalMs * 90;
  95     ++frame_id;
  96     time_interval = testing_clock_.NowTicks() - start_time;
  97   }  while (time_interval.InSeconds() < kIntervalTime1S);
  98   // Get logging data.
  99   FrameRawMap frame_map =  logging_->GetFrameRawData();
 100   // Size of map should be equal to the number of frames logged.
 101   EXPECT_EQ(frame_id, frame_map.size());
 102   // Verify stats.
 103   const FrameStatsMap* frame_stats =
 104       logging_->GetFrameStatsData(testing_clock_.NowTicks());
 105   // Size of stats equals the number of events.
 106   EXPECT_EQ(1u, frame_stats->size());
 107   FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured);
 108   EXPECT_TRUE(it != frame_stats->end());
 109   EXPECT_NEAR(30.3, it->second->framerate_fps, 0.1);
 110   EXPECT_NEAR(8 * kBaseFrameSizeBytes / (kFrameIntervalMs * 1000),
 111       it->second->bitrate_kbps, kRandomSizeInterval);
 112   EXPECT_EQ(0, it->second->max_delay_ms);
 113   EXPECT_EQ(0, it->second->min_delay_ms);
 114   EXPECT_EQ(0, it->second->avg_delay_ms);
 115 }
 116
 117 TEST_F(TestLogging, FrameLoggingWithDelay) {
 118   // Average packet size.
 119   const int kPlayoutDelayMs = 50;
 120   const int kRandomSizeInterval = 20;
 121   base::TimeTicks start_time = testing_clock_.NowTicks();
 122   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 123   uint32 rtp_timestamp = 0;
 124   uint32 frame_id = 0;
 125   do {
 126     int delay = kPlayoutDelayMs +
 127         base::RandInt(-kRandomSizeInterval, kRandomSizeInterval);
 128     logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(),
 129         kAudioFrameCaptured, rtp_timestamp, frame_id,
 130         base::TimeDelta::FromMilliseconds(delay));
 131     testing_clock_.Advance(
 132         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 133     rtp_timestamp += kFrameIntervalMs * 90;
 134     ++frame_id;
 135     time_interval = testing_clock_.NowTicks() - start_time;
 136   }  while (time_interval.InSeconds() < kIntervalTime1S);
 137   // Get logging data.
 138   FrameRawMap frame_map =  logging_->GetFrameRawData();
 139   // Size of map should be equal to the number of frames logged.
 140   EXPECT_EQ(frame_id, frame_map.size());
 141   // Verify stats.
 142   const FrameStatsMap* frame_stats =
 143       logging_->GetFrameStatsData(testing_clock_.NowTicks());
 144   // Size of stats equals the number of events.
 145   EXPECT_EQ(1u, frame_stats->size());
 146   FrameStatsMap::const_iterator it = frame_stats->find(kAudioFrameCaptured);
 147   EXPECT_TRUE(it != frame_stats->end());
 148   EXPECT_NEAR(30.3, it->second->framerate_fps, 0.1);
 149   EXPECT_EQ(0, it->second->bitrate_kbps);
 150   EXPECT_GE(kPlayoutDelayMs + kRandomSizeInterval, it->second->max_delay_ms);
 151   EXPECT_LE(kPlayoutDelayMs - kRandomSizeInterval, it->second->min_delay_ms);
 152   EXPECT_NEAR(kPlayoutDelayMs, it->second->avg_delay_ms,
 153       0.2 * kRandomSizeInterval);
 154 }
 155
 156 TEST_F(TestLogging, MultipleEventFrameLogging) {
 157   base::TimeTicks start_time = testing_clock_.NowTicks();
 158   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 159   uint32 rtp_timestamp = 0;
 160   uint32 frame_id = 0;
 161   do {
 162     logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured,
 163                                rtp_timestamp, frame_id);
 164     if (frame_id % 2) {
 165       logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(),
 166           kAudioFrameEncoded, rtp_timestamp, frame_id, 1500);
 167     } else if (frame_id % 3) {
 168       logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded,
 169                                  rtp_timestamp, frame_id);
 170     } else {
 171       logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(),
 172           kVideoRenderDelay, rtp_timestamp, frame_id,
 173           base::TimeDelta::FromMilliseconds(20));
 174     }
 175     testing_clock_.Advance(
 176         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 177     rtp_timestamp += kFrameIntervalMs * 90;
 178     ++frame_id;
 179     time_interval = testing_clock_.NowTicks() - start_time;
 180   }  while (time_interval.InSeconds() < kIntervalTime1S);
 181   // Get logging data.
 182   FrameRawMap frame_map = logging_->GetFrameRawData();
 183   // Size of map should be equal to the number of frames logged.
 184   EXPECT_EQ(frame_id, frame_map.size());
 185   // Multiple events captured per frame.
 186 }
 187
 188 TEST_F(TestLogging, PacketLogging) {
 189   const int kNumPacketsPerFrame = 10;
 190   const int kBaseSize = 2500;
 191   const int kSizeInterval = 100;
 192   base::TimeTicks start_time = testing_clock_.NowTicks();
 193   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 194   uint32 rtp_timestamp = 0;
 195   uint32 frame_id = 0;
 196   do {
 197     for (int i = 0; i < kNumPacketsPerFrame; ++i) {
 198       int size = kBaseSize + base::RandInt(-kSizeInterval, kSizeInterval);
 199       logging_->InsertPacketEvent(testing_clock_.NowTicks(), kPacketSentToPacer,
 200           rtp_timestamp, frame_id, i, kNumPacketsPerFrame, size);
 201     }
 202     testing_clock_.Advance(
 203         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 204     rtp_timestamp += kFrameIntervalMs * 90;
 205     ++frame_id;
 206     time_interval = testing_clock_.NowTicks() - start_time;
 207   }  while (time_interval.InSeconds() < kIntervalTime1S);
 208   // Get logging data.
 209   PacketRawMap raw_map = logging_->GetPacketRawData();
 210   // Size of map should be equal to the number of frames logged.
 211   EXPECT_EQ(frame_id, raw_map.size());
 212   // Verify stats.
 213   const PacketStatsMap* stats_map =
 214       logging_->GetPacketStatsData(testing_clock_.NowTicks());
 215   // Size of stats equals the number of events.
 216   EXPECT_EQ(1u, stats_map->size());
 217   PacketStatsMap::const_iterator it = stats_map->find(kPacketSentToPacer);
 218   EXPECT_TRUE(it != stats_map->end());
 219   // We only store the bitrate as a packet statistic.
 220   EXPECT_NEAR(8 * kNumPacketsPerFrame * kBaseSize / (kFrameIntervalMs * 1000),
 221       it->second, kSizeInterval);
 222 }
 223
 224 TEST_F(TestLogging, GenericLogging) {
 225   // Insert multiple generic types.
 226   const size_t kNumRuns = 1000;
 227   const int kBaseValue = 20;
 228   for (size_t i = 0; i < kNumRuns; ++i) {
 229     int value = kBaseValue + base::RandInt(-5, 5);
 230     logging_->InsertGenericEvent(testing_clock_.NowTicks(), kRttMs, value);
 231     if (i % 2) {
 232       logging_->InsertGenericEvent(testing_clock_.NowTicks(), kPacketLoss,
 233                                    value);
 234     }
 235     if (!(i % 4)) {
 236       logging_->InsertGenericEvent(testing_clock_.NowTicks(), kJitterMs, value);
 237     }
 238   }
 239   GenericRawMap raw_map = logging_->GetGenericRawData();
 240   const GenericStatsMap* stats_map = logging_->GetGenericStatsData();
 241   // Size of generic map = number of different events.
 242   EXPECT_EQ(3u, raw_map.size());
 243   EXPECT_EQ(3u, stats_map->size());
 244   // Raw events - size of internal map = number of calls.
 245   GenericRawMap::iterator rit = raw_map.find(kRttMs);
 246   EXPECT_EQ(kNumRuns, rit->second.value.size());
 247   EXPECT_EQ(kNumRuns, rit->second.timestamp.size());
 248   rit = raw_map.find(kPacketLoss);
 249   EXPECT_EQ(kNumRuns / 2, rit->second.value.size());
 250   EXPECT_EQ(kNumRuns / 2, rit->second.timestamp.size());
 251   rit = raw_map.find(kJitterMs);
 252   EXPECT_EQ(kNumRuns / 4, rit->second.value.size());
 253   EXPECT_EQ(kNumRuns / 4, rit->second.timestamp.size());
 254   // Stats - one value per event.
 255   GenericStatsMap::const_iterator sit = stats_map->find(kRttMs);
 256   EXPECT_NEAR(kBaseValue, sit->second, 2.5);
 257   sit = stats_map->find(kPacketLoss);
 258   EXPECT_NEAR(kBaseValue, sit->second, 2.5);
 259   sit = stats_map->find(kJitterMs);
 260   EXPECT_NEAR(kBaseValue, sit->second, 2.5);
 261 }
 262
 263 TEST_F(TestLogging, RtcpMultipleEventFrameLogging) {
 264   base::TimeTicks start_time = testing_clock_.NowTicks();
 265   base::TimeDelta time_interval = testing_clock_.NowTicks() - start_time;
 266   uint32 rtp_timestamp = 0;
 267   uint32 frame_id = 0;
 268   do {
 269     logging_->InsertFrameEvent(testing_clock_.NowTicks(), kAudioFrameCaptured,
 270                                rtp_timestamp, frame_id);
 271     if (frame_id % 2) {
 272       logging_->InsertFrameEventWithSize(testing_clock_.NowTicks(),
 273           kAudioFrameEncoded, rtp_timestamp, frame_id, 1500);
 274     } else if (frame_id % 3) {
 275       logging_->InsertFrameEvent(testing_clock_.NowTicks(), kVideoFrameDecoded,
 276                                  rtp_timestamp, frame_id);
 277     } else {
 278       logging_->InsertFrameEventWithDelay(testing_clock_.NowTicks(),
 279           kVideoRenderDelay, rtp_timestamp, frame_id,
 280           base::TimeDelta::FromMilliseconds(20));
 281     }
 282     testing_clock_.Advance(
 283         base::TimeDelta::FromMilliseconds(kFrameIntervalMs));
 284     rtp_timestamp += kFrameIntervalMs * 90;
 285     ++frame_id;
 286     time_interval = testing_clock_.NowTicks() - start_time;
 287   }  while (time_interval.InSeconds() < kIntervalTime1S);
 288   // Get logging data.
 289   FrameRawMap frame_map = logging_->GetFrameRawData();
 290   // Size of map should be equal to the number of frames logged.
 291   EXPECT_EQ(frame_id, frame_map.size());
 292   // Multiple events captured per frame.
 293
 294   AudioRtcpRawMap audio_rtcp = logging_->GetAudioRtcpRawData();
 295   EXPECT_EQ(0u, audio_rtcp.size());
 296
 297   VideoRtcpRawMap video_rtcp = logging_->GetVideoRtcpRawData();
 298   EXPECT_EQ((frame_id + 1) / 2, video_rtcp.size());
 299 }
 300
 301 }  // namespace cast
 302 }  // namespace media