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, Capture) { 69 Init(VIDEO_EVENT); 70 71 uint32 rtp_timestamp = 0; 72 uint32 frame_id = 0; 73 int num_frames = 10; 74 base::TimeTicks start_time = sender_clock_->NowTicks(); 75 for (int i = 0; i < num_frames; i++) { 76 cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), 77 FRAME_CAPTURE_BEGIN, 78 VIDEO_EVENT, 79 rtp_timestamp, 80 frame_id); 81 82 AdvanceClocks(base::TimeDelta::FromMicroseconds(34567)); 83 rtp_timestamp += 90; 84 frame_id++; 85 } 86 87 base::TimeTicks end_time = sender_clock_->NowTicks(); 88 89 StatsEventSubscriber::StatsMap stats_map; 90 subscriber_->GetStatsInternal(&stats_map); 91 92 StatsEventSubscriber::StatsMap::iterator it = 93 stats_map.find(StatsEventSubscriber::CAPTURE_FPS); 94 ASSERT_NE(it, stats_map.end()); 95 96 base::TimeDelta duration = end_time - start_time; 97 EXPECT_DOUBLE_EQ( 98 it->second, 99 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000); 100 } 101 102 TEST_F(StatsEventSubscriberTest, Encode) { 103 Init(VIDEO_EVENT); 104 105 uint32 rtp_timestamp = 0; 106 uint32 frame_id = 0; 107 int num_frames = 10; 108 base::TimeTicks start_time = sender_clock_->NowTicks(); 109 int total_size = 0; 110 for (int i = 0; i < num_frames; i++) { 111 int size = 1000 + base::RandInt(-100, 100); 112 total_size += size; 113 cast_environment_->Logging()->InsertEncodedFrameEvent( 114 sender_clock_->NowTicks(), 115 FRAME_ENCODED, VIDEO_EVENT, 116 rtp_timestamp, 117 frame_id, 118 size, 119 true, 120 5678); 121 122 AdvanceClocks(base::TimeDelta::FromMicroseconds(35678)); 123 rtp_timestamp += 90; 124 frame_id++; 125 } 126 127 base::TimeTicks end_time = sender_clock_->NowTicks(); 128 129 StatsEventSubscriber::StatsMap stats_map; 130 subscriber_->GetStatsInternal(&stats_map); 131 132 StatsEventSubscriber::StatsMap::iterator it = 133 stats_map.find(StatsEventSubscriber::ENCODE_FPS); 134 ASSERT_NE(it, stats_map.end()); 135 136 base::TimeDelta duration = end_time - start_time; 137 EXPECT_DOUBLE_EQ( 138 it->second, 139 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000); 140 141 it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS); 142 ASSERT_NE(it, stats_map.end()); 143 144 EXPECT_DOUBLE_EQ(it->second, 145 static_cast<double>(total_size) / duration.InMillisecondsF() * 8); 146 } 147 148 TEST_F(StatsEventSubscriberTest, Decode) { 149 Init(VIDEO_EVENT); 150 151 uint32 rtp_timestamp = 0; 152 uint32 frame_id = 0; 153 int num_frames = 10; 154 base::TimeTicks start_time = sender_clock_->NowTicks(); 155 for (int i = 0; i < num_frames; i++) { 156 cast_environment_->Logging()->InsertFrameEvent(receiver_clock_.NowTicks(), 157 FRAME_DECODED, VIDEO_EVENT, 158 rtp_timestamp, 159 frame_id); 160 161 AdvanceClocks(base::TimeDelta::FromMicroseconds(36789)); 162 rtp_timestamp += 90; 163 frame_id++; 164 } 165 166 base::TimeTicks end_time = sender_clock_->NowTicks(); 167 168 StatsEventSubscriber::StatsMap stats_map; 169 subscriber_->GetStatsInternal(&stats_map); 170 171 StatsEventSubscriber::StatsMap::iterator it = 172 stats_map.find(StatsEventSubscriber::DECODE_FPS); 173 ASSERT_NE(it, stats_map.end()); 174 175 base::TimeDelta duration = end_time - start_time; 176 EXPECT_DOUBLE_EQ( 177 it->second, 178 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000); 179 } 180 181 TEST_F(StatsEventSubscriberTest, PlayoutDelay) { 182 Init(VIDEO_EVENT); 183 184 uint32 rtp_timestamp = 0; 185 uint32 frame_id = 0; 186 int num_frames = 10; 187 int total_delay_ms = 0; 188 for (int i = 0; i < num_frames; i++) { 189 int delay_ms = base::RandInt(-50, 50); 190 base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms); 191 total_delay_ms += delay_ms; 192 cast_environment_->Logging()->InsertFrameEventWithDelay( 193 receiver_clock_.NowTicks(), 194 FRAME_PLAYOUT, 195 VIDEO_EVENT, 196 rtp_timestamp, 197 frame_id, 198 delay); 199 200 AdvanceClocks(base::TimeDelta::FromMicroseconds(37890)); 201 rtp_timestamp += 90; 202 frame_id++; 203 } 204 205 StatsEventSubscriber::StatsMap stats_map; 206 subscriber_->GetStatsInternal(&stats_map); 207 208 StatsEventSubscriber::StatsMap::iterator it = 209 stats_map.find(StatsEventSubscriber::AVG_PLAYOUT_DELAY_MS); 210 ASSERT_NE(it, stats_map.end()); 211 212 EXPECT_DOUBLE_EQ( 213 it->second, static_cast<double>(total_delay_ms) / num_frames); 214 } 215 216 TEST_F(StatsEventSubscriberTest, E2ELatency) { 217 Init(VIDEO_EVENT); 218 219 uint32 rtp_timestamp = 0; 220 uint32 frame_id = 0; 221 int num_frames = 10; 222 base::TimeDelta total_latency; 223 for (int i = 0; i < num_frames; i++) { 224 cast_environment_->Logging()->InsertFrameEvent(sender_clock_->NowTicks(), 225 FRAME_CAPTURE_BEGIN, 226 VIDEO_EVENT, 227 rtp_timestamp, 228 frame_id); 229 230 int latency_micros = 100000 + base::RandInt(-5000, 50000); 231 base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros); 232 AdvanceClocks(latency); 233 234 int delay_micros = base::RandInt(-50000, 50000); 235 base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros); 236 total_latency += latency + delay; 237 238 cast_environment_->Logging()->InsertFrameEventWithDelay( 239 receiver_clock_.NowTicks(), 240 FRAME_PLAYOUT, 241 VIDEO_EVENT, 242 rtp_timestamp, 243 frame_id, 244 delay); 245 246 rtp_timestamp += 90; 247 frame_id++; 248 } 249 250 StatsEventSubscriber::StatsMap stats_map; 251 subscriber_->GetStatsInternal(&stats_map); 252 253 StatsEventSubscriber::StatsMap::iterator it = 254 stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS); 255 ASSERT_NE(it, stats_map.end()); 256 257 EXPECT_DOUBLE_EQ( 258 it->second, total_latency.InMillisecondsF() / num_frames); 259 } 260 261 TEST_F(StatsEventSubscriberTest, Packets) { 262 Init(VIDEO_EVENT); 263 264 uint32 rtp_timestamp = 0; 265 int num_packets = 10; 266 int num_latency_recorded_packets = 0; 267 base::TimeTicks start_time = sender_clock_->NowTicks(); 268 int total_size = 0; 269 int retransmit_total_size = 0; 270 base::TimeDelta total_latency; 271 int num_packets_sent = 0; 272 int num_packets_retransmitted = 0; 273 // Every 2nd packet will be retransmitted once. 274 // Every 4th packet will be retransmitted twice. 275 // Every 8th packet will be retransmitted 3 times. 276 for (int i = 0; i < num_packets; i++) { 277 int size = 1000 + base::RandInt(-100, 100); 278 total_size += size; 279 280 cast_environment_->Logging()->InsertPacketEvent(sender_clock_->NowTicks(), 281 PACKET_SENT_TO_NETWORK, 282 VIDEO_EVENT, 283 rtp_timestamp, 284 0, 285 i, 286 num_packets - 1, 287 size); 288 num_packets_sent++; 289 290 int latency_micros = 20000 + base::RandInt(-10000, 10000); 291 base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros); 292 // Latency is only recorded for packets that aren't retransmitted. 293 if (i % 2 != 0) { 294 total_latency += latency; 295 num_latency_recorded_packets++; 296 } 297 298 AdvanceClocks(latency); 299 300 base::TimeTicks received_time = receiver_clock_.NowTicks(); 301 302 // Retransmission 1. 303 AdvanceClocks(base::TimeDelta::FromMicroseconds(12345)); 304 if (i % 2 == 0) { 305 cast_environment_->Logging()->InsertPacketEvent( 306 receiver_clock_.NowTicks(), 307 PACKET_RETRANSMITTED, 308 VIDEO_EVENT, 309 rtp_timestamp, 310 0, 311 i, 312 num_packets - 1, 313 size); 314 retransmit_total_size += size; 315 num_packets_sent++; 316 num_packets_retransmitted++; 317 } 318 319 // Retransmission 2. 320 AdvanceClocks(base::TimeDelta::FromMicroseconds(13456)); 321 if (i % 4 == 0) { 322 cast_environment_->Logging()->InsertPacketEvent( 323 receiver_clock_.NowTicks(), 324 PACKET_RETRANSMITTED, 325 VIDEO_EVENT, 326 rtp_timestamp, 327 0, 328 i, 329 num_packets - 1, 330 size); 331 retransmit_total_size += size; 332 num_packets_sent++; 333 num_packets_retransmitted++; 334 } 335 336 // Retransmission 3. 337 AdvanceClocks(base::TimeDelta::FromMicroseconds(14567)); 338 if (i % 8 == 0) { 339 cast_environment_->Logging()->InsertPacketEvent( 340 receiver_clock_.NowTicks(), 341 PACKET_RETRANSMITTED, 342 VIDEO_EVENT, 343 rtp_timestamp, 344 0, 345 i, 346 num_packets - 1, 347 size); 348 retransmit_total_size += size; 349 num_packets_sent++; 350 num_packets_retransmitted++; 351 } 352 353 cast_environment_->Logging()->InsertPacketEvent(received_time, 354 PACKET_RECEIVED, 355 VIDEO_EVENT, 356 rtp_timestamp, 357 0, 358 i, 359 num_packets - 1, 360 size); 361 } 362 363 base::TimeTicks end_time = sender_clock_->NowTicks(); 364 base::TimeDelta duration = end_time - start_time; 365 366 StatsEventSubscriber::StatsMap stats_map; 367 subscriber_->GetStatsInternal(&stats_map); 368 369 // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS, 370 // and PACKET_LOSS_FRACTION. 371 StatsEventSubscriber::StatsMap::iterator it = 372 stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS); 373 ASSERT_NE(it, stats_map.end()); 374 375 EXPECT_DOUBLE_EQ( 376 it->second, 377 total_latency.InMillisecondsF() / num_latency_recorded_packets); 378 379 it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS); 380 ASSERT_NE(it, stats_map.end()); 381 382 EXPECT_DOUBLE_EQ(it->second, 383 static_cast<double>(total_size) / duration.InMillisecondsF() * 8); 384 385 it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS); 386 ASSERT_NE(it, stats_map.end()); 387 388 EXPECT_DOUBLE_EQ(it->second, 389 static_cast<double>(retransmit_total_size) / 390 duration.InMillisecondsF() * 8); 391 392 it = stats_map.find(StatsEventSubscriber::PACKET_LOSS_FRACTION); 393 ASSERT_NE(it, stats_map.end()); 394 395 EXPECT_DOUBLE_EQ( 396 it->second, 397 static_cast<double>(num_packets_retransmitted) / num_packets_sent); 398 } 399 400 } // namespace cast 401 } // namespace media 402
