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:
StatsEventSubscriberTest()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
~StatsEventSubscriberTest()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
AdvanceClocks(base::TimeDelta delta)48 void AdvanceClocks(base::TimeDelta delta) {
49 sender_clock_->Advance(delta);
50 receiver_clock_.Advance(delta);
51 }
52
Init(EventMediaType event_media_type)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
TEST_F(StatsEventSubscriberTest,CaptureEncode)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
TEST_F(StatsEventSubscriberTest,Encode)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
TEST_F(StatsEventSubscriberTest,Decode)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
TEST_F(StatsEventSubscriberTest,PlayoutDelay)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
TEST_F(StatsEventSubscriberTest,E2ELatency)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
TEST_F(StatsEventSubscriberTest,Packets)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
487