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 "media/cast/logging/stats_event_subscriber.h"
6
7 #include <stddef.h>
8 #include <stdint.h>
9
10 #include <memory>
11 #include <utility>
12
13 #include "base/memory/ref_counted.h"
14 #include "base/rand_util.h"
15 #include "base/test/simple_test_tick_clock.h"
16 #include "base/time/tick_clock.h"
17 #include "base/values.h"
18 #include "media/base/fake_single_thread_task_runner.h"
19 #include "media/cast/cast_environment.h"
20 #include "media/cast/logging/logging_defines.h"
21 #include "media/cast/test/fake_receiver_time_offset_estimator.h"
22 #include "testing/gtest/include/gtest/gtest.h"
23
24 namespace {
25 const int kReceiverOffsetSecs = 100;
26 }
27
28 namespace media {
29 namespace cast {
30
31 class StatsEventSubscriberTest : public ::testing::Test {
32 protected:
StatsEventSubscriberTest()33 StatsEventSubscriberTest()
34 : task_runner_(new FakeSingleThreadTaskRunner(&sender_clock_)),
35 cast_environment_(new CastEnvironment(&sender_clock_,
36 task_runner_,
37 task_runner_,
38 task_runner_)),
39 fake_offset_estimator_(
40 base::TimeDelta::FromSeconds(kReceiverOffsetSecs)) {
41 receiver_clock_.Advance(base::TimeDelta::FromSeconds(kReceiverOffsetSecs));
42 cast_environment_->logger()->Subscribe(&fake_offset_estimator_);
43 }
44
~StatsEventSubscriberTest()45 ~StatsEventSubscriberTest() override {
46 if (subscriber_.get())
47 cast_environment_->logger()->Unsubscribe(subscriber_.get());
48 cast_environment_->logger()->Unsubscribe(&fake_offset_estimator_);
49 }
50
AdvanceClocks(base::TimeDelta delta)51 void AdvanceClocks(base::TimeDelta delta) {
52 task_runner_->Sleep(delta);
53 receiver_clock_.Advance(delta);
54 }
55
Init(EventMediaType event_media_type)56 void Init(EventMediaType event_media_type) {
57 DCHECK(!subscriber_.get());
58 subscriber_.reset(new StatsEventSubscriber(
59 event_media_type, cast_environment_->Clock(), &fake_offset_estimator_));
60 cast_environment_->logger()->Subscribe(subscriber_.get());
61 }
62
63 base::SimpleTestTickClock sender_clock_;
64 base::SimpleTestTickClock receiver_clock_;
65 scoped_refptr<FakeSingleThreadTaskRunner> task_runner_;
66 scoped_refptr<CastEnvironment> cast_environment_;
67 test::FakeReceiverTimeOffsetEstimator fake_offset_estimator_;
68 std::unique_ptr<StatsEventSubscriber> subscriber_;
69 };
70
TEST_F(StatsEventSubscriberTest,CaptureEncode)71 TEST_F(StatsEventSubscriberTest, CaptureEncode) {
72 Init(VIDEO_EVENT);
73
74 RtpTimeTicks rtp_timestamp;
75 FrameId frame_id = FrameId::first();
76 int extra_frames = 50;
77 // Only the first |extra_frames| frames logged will be taken into account
78 // when computing dropped frames.
79 int num_frames = StatsEventSubscriber::kMaxFrameInfoMapSize + 50;
80 int dropped_frames = 0;
81 base::TimeTicks start_time = sender_clock_.NowTicks();
82 // Drop half the frames during the encode step.
83 for (int i = 0; i < num_frames; i++) {
84 std::unique_ptr<FrameEvent> capture_begin_event(new FrameEvent());
85 capture_begin_event->timestamp = sender_clock_.NowTicks();
86 capture_begin_event->type = FRAME_CAPTURE_BEGIN;
87 capture_begin_event->media_type = VIDEO_EVENT;
88 capture_begin_event->rtp_timestamp = rtp_timestamp;
89 cast_environment_->logger()->DispatchFrameEvent(
90 std::move(capture_begin_event));
91
92 AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
93 std::unique_ptr<FrameEvent> capture_end_event(new FrameEvent());
94 capture_end_event->timestamp = sender_clock_.NowTicks();
95 capture_end_event->type = FRAME_CAPTURE_END;
96 capture_end_event->media_type = VIDEO_EVENT;
97 capture_end_event->rtp_timestamp = rtp_timestamp;
98 cast_environment_->logger()->DispatchFrameEvent(
99 std::move(capture_end_event));
100
101 if (i % 2 == 0) {
102 AdvanceClocks(base::TimeDelta::FromMicroseconds(10));
103 std::unique_ptr<FrameEvent> encode_event(new FrameEvent());
104 encode_event->timestamp = sender_clock_.NowTicks();
105 encode_event->type = FRAME_ENCODED;
106 encode_event->media_type = VIDEO_EVENT;
107 encode_event->rtp_timestamp = rtp_timestamp;
108 encode_event->frame_id = frame_id;
109 encode_event->size = 1024;
110 encode_event->key_frame = true;
111 encode_event->target_bitrate = 5678;
112 encode_event->encoder_cpu_utilization = 9.10;
113 encode_event->idealized_bitrate_utilization = 11.12;
114 cast_environment_->logger()->DispatchFrameEvent(std::move(encode_event));
115 } else if (i < extra_frames) {
116 dropped_frames++;
117 }
118 AdvanceClocks(base::TimeDelta::FromMicroseconds(34567));
119 rtp_timestamp += RtpTimeDelta::FromTicks(90);
120 frame_id++;
121 }
122
123 base::TimeTicks end_time = sender_clock_.NowTicks();
124
125 StatsEventSubscriber::StatsMap stats_map;
126 subscriber_->GetStatsInternal(&stats_map);
127
128 auto it = stats_map.find(StatsEventSubscriber::CAPTURE_FPS);
129 ASSERT_TRUE(it != stats_map.end());
130
131 base::TimeDelta duration = end_time - start_time;
132 EXPECT_DOUBLE_EQ(
133 it->second,
134 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
135
136 it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_CAPTURED);
137 ASSERT_TRUE(it != stats_map.end());
138
139 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_frames));
140
141 it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_DROPPED_BY_ENCODER);
142 ASSERT_TRUE(it != stats_map.end());
143
144 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(dropped_frames));
145
146 it = stats_map.find(StatsEventSubscriber::AVG_CAPTURE_LATENCY_MS);
147 ASSERT_TRUE(it != stats_map.end());
148
149 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(0.01));
150 }
151
TEST_F(StatsEventSubscriberTest,Encode)152 TEST_F(StatsEventSubscriberTest, Encode) {
153 Init(VIDEO_EVENT);
154
155 RtpTimeTicks rtp_timestamp;
156 FrameId frame_id = FrameId::first();
157 int num_frames = 10;
158 base::TimeTicks start_time = sender_clock_.NowTicks();
159 AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
160 base::TimeTicks first_event_time = sender_clock_.NowTicks();
161 base::TimeTicks last_event_time;
162 int total_size = 0;
163 for (int i = 0; i < num_frames; i++) {
164 int size = 1000 + base::RandInt(-100, 100);
165 total_size += size;
166 std::unique_ptr<FrameEvent> encode_event(new FrameEvent());
167 encode_event->timestamp = sender_clock_.NowTicks();
168 encode_event->type = FRAME_ENCODED;
169 encode_event->media_type = VIDEO_EVENT;
170 encode_event->rtp_timestamp = rtp_timestamp;
171 encode_event->frame_id = frame_id;
172 encode_event->size = size;
173 encode_event->key_frame = true;
174 encode_event->target_bitrate = 5678;
175 encode_event->encoder_cpu_utilization = 9.10;
176 encode_event->idealized_bitrate_utilization = 11.12;
177 cast_environment_->logger()->DispatchFrameEvent(std::move(encode_event));
178 last_event_time = sender_clock_.NowTicks();
179
180 AdvanceClocks(base::TimeDelta::FromMicroseconds(35678));
181 rtp_timestamp += RtpTimeDelta::FromTicks(90);
182 frame_id++;
183 }
184
185 base::TimeTicks end_time = sender_clock_.NowTicks();
186
187 StatsEventSubscriber::StatsMap stats_map;
188 subscriber_->GetStatsInternal(&stats_map);
189
190 auto it = stats_map.find(StatsEventSubscriber::ENCODE_FPS);
191 ASSERT_TRUE(it != stats_map.end());
192
193 base::TimeDelta duration = end_time - start_time;
194 EXPECT_DOUBLE_EQ(
195 it->second,
196 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
197
198 it = stats_map.find(StatsEventSubscriber::ENCODE_KBPS);
199 ASSERT_TRUE(it != stats_map.end());
200
201 EXPECT_DOUBLE_EQ(it->second,
202 static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
203
204 it = stats_map.find(StatsEventSubscriber::FIRST_EVENT_TIME_MS);
205 ASSERT_TRUE(it != stats_map.end());
206
207 EXPECT_DOUBLE_EQ(
208 it->second,
209 (first_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
210
211 it = stats_map.find(StatsEventSubscriber::LAST_EVENT_TIME_MS);
212 ASSERT_TRUE(it != stats_map.end());
213
214 EXPECT_DOUBLE_EQ(
215 it->second,
216 (last_event_time - base::TimeTicks::UnixEpoch()).InMillisecondsF());
217 }
218
TEST_F(StatsEventSubscriberTest,Decode)219 TEST_F(StatsEventSubscriberTest, Decode) {
220 Init(VIDEO_EVENT);
221
222 RtpTimeTicks rtp_timestamp;
223 FrameId frame_id = FrameId::first();
224 int num_frames = 10;
225 base::TimeTicks start_time = sender_clock_.NowTicks();
226 for (int i = 0; i < num_frames; i++) {
227 std::unique_ptr<FrameEvent> decode_event(new FrameEvent());
228 decode_event->timestamp = receiver_clock_.NowTicks();
229 decode_event->type = FRAME_DECODED;
230 decode_event->media_type = VIDEO_EVENT;
231 decode_event->rtp_timestamp = rtp_timestamp;
232 decode_event->frame_id = frame_id;
233 cast_environment_->logger()->DispatchFrameEvent(std::move(decode_event));
234
235 AdvanceClocks(base::TimeDelta::FromMicroseconds(36789));
236 rtp_timestamp += RtpTimeDelta::FromTicks(90);
237 frame_id++;
238 }
239
240 base::TimeTicks end_time = sender_clock_.NowTicks();
241
242 StatsEventSubscriber::StatsMap stats_map;
243 subscriber_->GetStatsInternal(&stats_map);
244
245 auto it = stats_map.find(StatsEventSubscriber::DECODE_FPS);
246 ASSERT_TRUE(it != stats_map.end());
247
248 base::TimeDelta duration = end_time - start_time;
249 EXPECT_DOUBLE_EQ(
250 it->second,
251 static_cast<double>(num_frames) / duration.InMillisecondsF() * 1000);
252 }
253
TEST_F(StatsEventSubscriberTest,PlayoutDelay)254 TEST_F(StatsEventSubscriberTest, PlayoutDelay) {
255 Init(VIDEO_EVENT);
256
257 RtpTimeTicks rtp_timestamp;
258 FrameId frame_id = FrameId::first();
259 int num_frames = 10;
260 int late_frames = 0;
261 for (int i = 0, delay_ms = -50; i < num_frames; i++, delay_ms += 10) {
262 base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_ms);
263 if (delay_ms > 0)
264 late_frames++;
265 std::unique_ptr<FrameEvent> playout_event(new FrameEvent());
266 playout_event->timestamp = receiver_clock_.NowTicks();
267 playout_event->type = FRAME_PLAYOUT;
268 playout_event->media_type = VIDEO_EVENT;
269 playout_event->rtp_timestamp = rtp_timestamp;
270 playout_event->frame_id = frame_id;
271 playout_event->delay_delta = delay;
272 cast_environment_->logger()->DispatchFrameEvent(std::move(playout_event));
273
274 AdvanceClocks(base::TimeDelta::FromMicroseconds(37890));
275 rtp_timestamp += RtpTimeDelta::FromTicks(90);
276 frame_id++;
277 }
278
279 StatsEventSubscriber::StatsMap stats_map;
280 subscriber_->GetStatsInternal(&stats_map);
281
282 auto it = stats_map.find(StatsEventSubscriber::NUM_FRAMES_LATE);
283 ASSERT_TRUE(it != stats_map.end());
284
285 EXPECT_DOUBLE_EQ(it->second, late_frames);
286 }
287
TEST_F(StatsEventSubscriberTest,E2ELatency)288 TEST_F(StatsEventSubscriberTest, E2ELatency) {
289 Init(VIDEO_EVENT);
290
291 RtpTimeTicks rtp_timestamp;
292 FrameId frame_id = FrameId::first();
293 int num_frames = 10;
294 base::TimeDelta total_latency;
295 for (int i = 0; i < num_frames; i++) {
296 std::unique_ptr<FrameEvent> capture_begin_event(new FrameEvent());
297 capture_begin_event->timestamp = sender_clock_.NowTicks();
298 capture_begin_event->type = FRAME_CAPTURE_BEGIN;
299 capture_begin_event->media_type = VIDEO_EVENT;
300 capture_begin_event->rtp_timestamp = rtp_timestamp;
301 cast_environment_->logger()->DispatchFrameEvent(
302 std::move(capture_begin_event));
303
304 int latency_micros = 100000 + base::RandInt(-5000, 50000);
305 base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
306 AdvanceClocks(latency);
307
308 int delay_micros = base::RandInt(-50000, 50000);
309 base::TimeDelta delay = base::TimeDelta::FromMilliseconds(delay_micros);
310 total_latency += latency;
311
312 std::unique_ptr<FrameEvent> playout_event(new FrameEvent());
313 playout_event->timestamp = receiver_clock_.NowTicks();
314 playout_event->type = FRAME_PLAYOUT;
315 playout_event->media_type = VIDEO_EVENT;
316 playout_event->rtp_timestamp = rtp_timestamp;
317 playout_event->frame_id = frame_id;
318 playout_event->delay_delta = delay;
319 cast_environment_->logger()->DispatchFrameEvent(std::move(playout_event));
320
321 rtp_timestamp += RtpTimeDelta::FromTicks(90);
322 frame_id++;
323 }
324
325 StatsEventSubscriber::StatsMap stats_map;
326 subscriber_->GetStatsInternal(&stats_map);
327
328 auto it = stats_map.find(StatsEventSubscriber::AVG_E2E_LATENCY_MS);
329 ASSERT_TRUE(it != stats_map.end());
330
331 EXPECT_DOUBLE_EQ(
332 it->second, total_latency.InMillisecondsF() / num_frames);
333 }
334
TEST_F(StatsEventSubscriberTest,Packets)335 TEST_F(StatsEventSubscriberTest, Packets) {
336 Init(VIDEO_EVENT);
337
338 RtpTimeTicks rtp_timestamp;
339 int num_packets = 10;
340 int num_latency_recorded_packets = 0;
341 base::TimeTicks start_time = sender_clock_.NowTicks();
342 int total_size = 0;
343 int retransmit_total_size = 0;
344 base::TimeDelta total_network_latency;
345 base::TimeDelta total_queueing_latency;
346 base::TimeDelta total_packet_latency;
347 int num_packets_transmitted = 0;
348 int num_packets_received = 0;
349 int num_packets_retransmitted = 0;
350 int num_packets_rtx_rejected = 0;
351
352 base::TimeTicks sender_encoded_time = sender_clock_.NowTicks();
353 base::TimeTicks receiver_encoded_time = receiver_clock_.NowTicks();
354 std::unique_ptr<FrameEvent> encode_event(new FrameEvent());
355 encode_event->timestamp = sender_encoded_time;
356 encode_event->type = FRAME_ENCODED;
357 encode_event->media_type = VIDEO_EVENT;
358 encode_event->rtp_timestamp = rtp_timestamp;
359 encode_event->frame_id = FrameId::first();
360 cast_environment_->logger()->DispatchFrameEvent(std::move(encode_event));
361
362 // Every 2nd packet will be retransmitted once.
363 // Every 4th packet will be retransmitted twice.
364 // Every 8th packet will be retransmitted 3 times + 1 rejected retransmission.
365 for (int i = 0; i < num_packets; i++) {
366 int size = 1000 + base::RandInt(-100, 100);
367 total_size += size;
368
369 std::unique_ptr<PacketEvent> send_event(new PacketEvent());
370 send_event->timestamp = sender_clock_.NowTicks();
371 send_event->type = PACKET_SENT_TO_NETWORK;
372 send_event->media_type = VIDEO_EVENT;
373 send_event->rtp_timestamp = rtp_timestamp;
374 send_event->frame_id = FrameId::first();
375 send_event->packet_id = i;
376 send_event->max_packet_id = num_packets - 1;
377 send_event->size = size;
378 cast_environment_->logger()->DispatchPacketEvent(std::move(send_event));
379
380 num_packets_transmitted++;
381 total_queueing_latency += sender_clock_.NowTicks() - sender_encoded_time;
382
383 int latency_micros = 20000 + base::RandInt(-10000, 10000);
384 base::TimeDelta latency = base::TimeDelta::FromMicroseconds(latency_micros);
385 // Latency is only recorded for packets that aren't retransmitted.
386 if (i % 2 != 0) {
387 total_network_latency += latency;
388 total_packet_latency +=
389 receiver_clock_.NowTicks() - receiver_encoded_time + latency;
390 num_latency_recorded_packets++;
391 }
392
393 AdvanceClocks(latency);
394
395 base::TimeTicks received_time = receiver_clock_.NowTicks();
396
397 // Retransmission 1.
398 AdvanceClocks(base::TimeDelta::FromMicroseconds(12345));
399 if (i % 2 == 0) {
400 std::unique_ptr<PacketEvent> retransmit_event(new PacketEvent());
401 retransmit_event->timestamp = receiver_clock_.NowTicks();
402 retransmit_event->type = PACKET_RETRANSMITTED;
403 retransmit_event->media_type = VIDEO_EVENT;
404 retransmit_event->rtp_timestamp = rtp_timestamp;
405 retransmit_event->frame_id = FrameId::first();
406 retransmit_event->packet_id = i;
407 retransmit_event->max_packet_id = num_packets - 1;
408 retransmit_event->size = size;
409 cast_environment_->logger()->DispatchPacketEvent(
410 std::move(retransmit_event));
411
412 retransmit_total_size += size;
413 num_packets_transmitted++;
414 num_packets_retransmitted++;
415 }
416
417 // Retransmission 2.
418 AdvanceClocks(base::TimeDelta::FromMicroseconds(13456));
419 if (i % 4 == 0) {
420 std::unique_ptr<PacketEvent> retransmit_event(new PacketEvent());
421 retransmit_event->timestamp = receiver_clock_.NowTicks();
422 retransmit_event->type = PACKET_RETRANSMITTED;
423 retransmit_event->media_type = VIDEO_EVENT;
424 retransmit_event->rtp_timestamp = rtp_timestamp;
425 retransmit_event->frame_id = FrameId::first();
426 retransmit_event->packet_id = i;
427 retransmit_event->max_packet_id = num_packets - 1;
428 retransmit_event->size = size;
429 cast_environment_->logger()->DispatchPacketEvent(
430 std::move(retransmit_event));
431
432 retransmit_total_size += size;
433 num_packets_transmitted++;
434 num_packets_retransmitted++;
435 }
436
437 // Retransmission 3.
438 AdvanceClocks(base::TimeDelta::FromMicroseconds(14567));
439 if (i % 8 == 0) {
440 std::unique_ptr<PacketEvent> retransmit_event(new PacketEvent());
441 retransmit_event->timestamp = receiver_clock_.NowTicks();
442 retransmit_event->type = PACKET_RETRANSMITTED;
443 retransmit_event->media_type = VIDEO_EVENT;
444 retransmit_event->rtp_timestamp = rtp_timestamp;
445 retransmit_event->frame_id = FrameId::first();
446 retransmit_event->packet_id = i;
447 retransmit_event->max_packet_id = num_packets - 1;
448 retransmit_event->size = size;
449 cast_environment_->logger()->DispatchPacketEvent(
450 std::move(retransmit_event));
451
452 std::unique_ptr<PacketEvent> reject_event(new PacketEvent());
453 reject_event->timestamp = receiver_clock_.NowTicks();
454 reject_event->type = PACKET_RTX_REJECTED;
455 reject_event->media_type = VIDEO_EVENT;
456 reject_event->rtp_timestamp = rtp_timestamp;
457 reject_event->frame_id = FrameId::first();
458 reject_event->packet_id = i;
459 reject_event->max_packet_id = num_packets - 1;
460 reject_event->size = size;
461 cast_environment_->logger()->DispatchPacketEvent(std::move(reject_event));
462
463 retransmit_total_size += size;
464 num_packets_transmitted++;
465 num_packets_retransmitted++;
466 num_packets_rtx_rejected++;
467 }
468
469 std::unique_ptr<PacketEvent> receive_event(new PacketEvent());
470 receive_event->timestamp = received_time;
471 receive_event->type = PACKET_RECEIVED;
472 receive_event->media_type = VIDEO_EVENT;
473 receive_event->rtp_timestamp = rtp_timestamp;
474 receive_event->frame_id = FrameId::first();
475 receive_event->packet_id = i;
476 receive_event->max_packet_id = num_packets - 1;
477 receive_event->size = size;
478 cast_environment_->logger()->DispatchPacketEvent(std::move(receive_event));
479
480 num_packets_received++;
481 }
482
483 base::TimeTicks end_time = sender_clock_.NowTicks();
484 base::TimeDelta duration = end_time - start_time;
485
486 StatsEventSubscriber::StatsMap stats_map;
487 subscriber_->GetStatsInternal(&stats_map);
488
489 // Measure AVG_NETWORK_LATENCY_MS, TRANSMISSION_KBPS, RETRANSMISSION_KBPS.
490 auto it = stats_map.find(StatsEventSubscriber::AVG_NETWORK_LATENCY_MS);
491 ASSERT_TRUE(it != stats_map.end());
492
493 EXPECT_DOUBLE_EQ(
494 it->second,
495 total_network_latency.InMillisecondsF() / num_latency_recorded_packets);
496
497 it = stats_map.find(StatsEventSubscriber::AVG_QUEUEING_LATENCY_MS);
498 ASSERT_TRUE(it != stats_map.end());
499
500 EXPECT_DOUBLE_EQ(
501 it->second,
502 total_queueing_latency.InMillisecondsF() / num_packets);
503
504 it = stats_map.find(StatsEventSubscriber::AVG_PACKET_LATENCY_MS);
505 ASSERT_TRUE(it != stats_map.end());
506
507 EXPECT_DOUBLE_EQ(
508 it->second,
509 total_packet_latency.InMillisecondsF() / num_latency_recorded_packets);
510
511 it = stats_map.find(StatsEventSubscriber::TRANSMISSION_KBPS);
512 ASSERT_TRUE(it != stats_map.end());
513
514 EXPECT_DOUBLE_EQ(it->second,
515 static_cast<double>(total_size) / duration.InMillisecondsF() * 8);
516
517 it = stats_map.find(StatsEventSubscriber::RETRANSMISSION_KBPS);
518 ASSERT_TRUE(it != stats_map.end());
519
520 EXPECT_DOUBLE_EQ(it->second,
521 static_cast<double>(retransmit_total_size) /
522 duration.InMillisecondsF() * 8);
523
524 it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_SENT);
525 ASSERT_TRUE(it != stats_map.end());
526
527 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets));
528
529 it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RECEIVED);
530 ASSERT_TRUE(it != stats_map.end());
531
532 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_received));
533
534 it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RETRANSMITTED);
535 ASSERT_TRUE(it != stats_map.end());
536
537 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_retransmitted));
538
539 it = stats_map.find(StatsEventSubscriber::NUM_PACKETS_RTX_REJECTED);
540 ASSERT_TRUE(it != stats_map.end());
541
542 EXPECT_DOUBLE_EQ(it->second, static_cast<double>(num_packets_rtx_rejected));
543 }
544
CheckHistogramHasValue(base::ListValue * values,const std::string & bucket,int expected_count)545 bool CheckHistogramHasValue(base::ListValue* values,
546 const std::string& bucket, int expected_count) {
547 for (size_t i = 0; i < values->GetSize(); ++i) {
548 const base::DictionaryValue* dict = NULL;
549 values->GetDictionary(i, &dict);
550 if (!dict->HasKey(bucket))
551 continue;
552 int bucket_count = 0;
553 if (!dict->GetInteger(bucket, &bucket_count))
554 return false;
555 return bucket_count == expected_count;
556 }
557 return false;
558 }
559
TEST_F(StatsEventSubscriberTest,Histograms)560 TEST_F(StatsEventSubscriberTest, Histograms) {
561 Init(VIDEO_EVENT);
562 AdvanceClocks(base::TimeDelta::FromMilliseconds(123));
563
564 RtpTimeTicks rtp_timestamp = RtpTimeTicks().Expand(UINT32_C(123));
565 FrameId frame_id = FrameId::first();
566
567 // 10 Frames with capture latency in the bucket of "10-14"ms.
568 // 10 Frames with encode time in the bucket of "15-19"ms.
569 for (int i = 0; i < 10; ++i) {
570 ++frame_id;
571 rtp_timestamp += RtpTimeDelta::FromTicks(1);
572
573 std::unique_ptr<FrameEvent> capture_begin_event(new FrameEvent());
574 capture_begin_event->timestamp = sender_clock_.NowTicks();
575 capture_begin_event->type = FRAME_CAPTURE_BEGIN;
576 capture_begin_event->media_type = VIDEO_EVENT;
577 capture_begin_event->rtp_timestamp = rtp_timestamp;
578 cast_environment_->logger()->DispatchFrameEvent(
579 std::move(capture_begin_event));
580
581 AdvanceClocks(base::TimeDelta::FromMilliseconds(10));
582 std::unique_ptr<FrameEvent> capture_end_event(new FrameEvent());
583 capture_end_event->timestamp = sender_clock_.NowTicks();
584 capture_end_event->type = FRAME_CAPTURE_END;
585 capture_end_event->media_type = VIDEO_EVENT;
586 capture_end_event->rtp_timestamp = rtp_timestamp;
587 cast_environment_->logger()->DispatchFrameEvent(
588 std::move(capture_end_event));
589
590 AdvanceClocks(base::TimeDelta::FromMilliseconds(15));
591 std::unique_ptr<FrameEvent> encode_event(new FrameEvent());
592 encode_event->timestamp = sender_clock_.NowTicks();
593 encode_event->type = FRAME_ENCODED;
594 encode_event->media_type = VIDEO_EVENT;
595 encode_event->rtp_timestamp = rtp_timestamp;
596 encode_event->frame_id = frame_id;
597 encode_event->size = 1024;
598 encode_event->key_frame = true;
599 encode_event->target_bitrate = 5678;
600 encode_event->encoder_cpu_utilization = 9.10;
601 encode_event->idealized_bitrate_utilization = 11.12;
602 cast_environment_->logger()->DispatchFrameEvent(std::move(encode_event));
603 }
604
605 // Send 3 packets for the last frame.
606 // Queueing latencies are 100ms, 200ms and 300ms.
607 for (int i = 0; i < 3; ++i) {
608 AdvanceClocks(base::TimeDelta::FromMilliseconds(100));
609 std::unique_ptr<PacketEvent> send_event(new PacketEvent());
610 send_event->timestamp = sender_clock_.NowTicks();
611 send_event->type = PACKET_SENT_TO_NETWORK;
612 send_event->media_type = VIDEO_EVENT;
613 send_event->rtp_timestamp = rtp_timestamp;
614 send_event->frame_id = FrameId::first();
615 send_event->packet_id = i;
616 send_event->max_packet_id = 2;
617 send_event->size = 123;
618 cast_environment_->logger()->DispatchPacketEvent(std::move(send_event));
619 }
620
621 // Receive 3 packets for the last frame.
622 // Network latencies are 100ms, 200ms and 300ms.
623 // Packet latencies are 400ms.
624 AdvanceClocks(base::TimeDelta::FromMilliseconds(100));
625 for (int i = 0; i < 3; ++i) {
626 std::unique_ptr<PacketEvent> receive_event(new PacketEvent());
627 receive_event->timestamp = receiver_clock_.NowTicks();
628 receive_event->type = PACKET_RECEIVED;
629 receive_event->media_type = VIDEO_EVENT;
630 receive_event->rtp_timestamp = rtp_timestamp;
631 receive_event->frame_id = FrameId::first();
632 receive_event->packet_id = i;
633 receive_event->max_packet_id = 2;
634 receive_event->size = 123;
635 cast_environment_->logger()->DispatchPacketEvent(std::move(receive_event));
636 }
637
638 std::unique_ptr<FrameEvent> playout_event(new FrameEvent());
639 playout_event->timestamp = receiver_clock_.NowTicks();
640 playout_event->type = FRAME_PLAYOUT;
641 playout_event->media_type = VIDEO_EVENT;
642 playout_event->rtp_timestamp = rtp_timestamp;
643 playout_event->frame_id = frame_id;
644 playout_event->delay_delta = base::TimeDelta::FromMilliseconds(100);
645 cast_environment_->logger()->DispatchFrameEvent(std::move(playout_event));
646
647 StatsEventSubscriber::SimpleHistogram* histogram;
648 std::unique_ptr<base::ListValue> values;
649
650 histogram = subscriber_->GetHistogramForTesting(
651 StatsEventSubscriber::CAPTURE_LATENCY_MS_HISTO);
652 ASSERT_TRUE(histogram);
653 values = histogram->GetHistogram();
654 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "10-14", 10));
655
656 histogram = subscriber_->GetHistogramForTesting(
657 StatsEventSubscriber::ENCODE_TIME_MS_HISTO);
658 ASSERT_TRUE(histogram);
659 values = histogram->GetHistogram();
660 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "15-19", 10));
661
662 histogram = subscriber_->GetHistogramForTesting(
663 StatsEventSubscriber::QUEUEING_LATENCY_MS_HISTO);
664 ASSERT_TRUE(histogram);
665 values = histogram->GetHistogram();
666 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
667 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "200-219", 1));
668 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "300-319", 1));
669
670 histogram = subscriber_->GetHistogramForTesting(
671 StatsEventSubscriber::NETWORK_LATENCY_MS_HISTO);
672 ASSERT_TRUE(histogram);
673 values = histogram->GetHistogram();
674 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
675 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "200-219", 1));
676 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "300-319", 1));
677
678 histogram = subscriber_->GetHistogramForTesting(
679 StatsEventSubscriber::PACKET_LATENCY_MS_HISTO);
680 ASSERT_TRUE(histogram);
681 values = histogram->GetHistogram();
682 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "400-419", 3));
683
684 histogram = subscriber_->GetHistogramForTesting(
685 StatsEventSubscriber::LATE_FRAME_MS_HISTO);
686 ASSERT_TRUE(histogram);
687 values = histogram->GetHistogram();
688 EXPECT_TRUE(CheckHistogramHasValue(values.get(), "100-119", 1));
689 }
690
691 } // namespace cast
692 } // namespace media
693