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 "base/logging.h"
8 #include "base/values.h"
9
10 #define STAT_ENUM_TO_STRING(enum) \
11 case enum: \
12 return #enum
13
14 namespace media {
15 namespace cast {
16
17 namespace {
18
19 using media::cast::CastLoggingEvent;
20 using media::cast::EventMediaType;
21
22 const size_t kMaxFrameEventTimeMapSize = 100;
23 const size_t kMaxPacketEventTimeMapSize = 1000;
24
IsReceiverEvent(CastLoggingEvent event)25 bool IsReceiverEvent(CastLoggingEvent event) {
26 return event == FRAME_DECODED
27 || event == FRAME_PLAYOUT
28 || event == FRAME_ACK_SENT
29 || event == PACKET_RECEIVED;
30 }
31
32 } // namespace
33
StatsEventSubscriber(EventMediaType event_media_type,base::TickClock * clock,ReceiverTimeOffsetEstimator * offset_estimator)34 StatsEventSubscriber::StatsEventSubscriber(
35 EventMediaType event_media_type,
36 base::TickClock* clock,
37 ReceiverTimeOffsetEstimator* offset_estimator)
38 : event_media_type_(event_media_type),
39 clock_(clock),
40 offset_estimator_(offset_estimator),
41 network_latency_datapoints_(0),
42 e2e_latency_datapoints_(0) {
43 DCHECK(event_media_type == AUDIO_EVENT || event_media_type == VIDEO_EVENT);
44 base::TimeTicks now = clock_->NowTicks();
45 start_time_ = now;
46 last_response_received_time_ = base::TimeTicks();
47 }
48
~StatsEventSubscriber()49 StatsEventSubscriber::~StatsEventSubscriber() {
50 DCHECK(thread_checker_.CalledOnValidThread());
51 }
52
OnReceiveFrameEvent(const FrameEvent & frame_event)53 void StatsEventSubscriber::OnReceiveFrameEvent(const FrameEvent& frame_event) {
54 DCHECK(thread_checker_.CalledOnValidThread());
55
56 CastLoggingEvent type = frame_event.type;
57 if (frame_event.media_type != event_media_type_)
58 return;
59
60 FrameStatsMap::iterator it = frame_stats_.find(type);
61 if (it == frame_stats_.end()) {
62 FrameLogStats stats;
63 stats.event_counter = 1;
64 stats.sum_size = frame_event.size;
65 stats.sum_delay = frame_event.delay_delta;
66 frame_stats_.insert(std::make_pair(type, stats));
67 } else {
68 ++(it->second.event_counter);
69 it->second.sum_size += frame_event.size;
70 it->second.sum_delay += frame_event.delay_delta;
71 }
72
73 if (type == FRAME_CAPTURE_BEGIN) {
74 RecordFrameCapturedTime(frame_event);
75 } else if (type == FRAME_PLAYOUT) {
76 RecordE2ELatency(frame_event);
77 }
78
79 if (IsReceiverEvent(type))
80 UpdateLastResponseTime(frame_event.timestamp);
81 }
82
OnReceivePacketEvent(const PacketEvent & packet_event)83 void StatsEventSubscriber::OnReceivePacketEvent(
84 const PacketEvent& packet_event) {
85 DCHECK(thread_checker_.CalledOnValidThread());
86
87 CastLoggingEvent type = packet_event.type;
88 if (packet_event.media_type != event_media_type_)
89 return;
90
91 PacketStatsMap::iterator it = packet_stats_.find(type);
92 if (it == packet_stats_.end()) {
93 PacketLogStats stats;
94 stats.event_counter = 1;
95 stats.sum_size = packet_event.size;
96 packet_stats_.insert(std::make_pair(type, stats));
97 } else {
98 ++(it->second.event_counter);
99 it->second.sum_size += packet_event.size;
100 }
101
102 if (type == PACKET_SENT_TO_NETWORK ||
103 type == PACKET_RECEIVED) {
104 RecordNetworkLatency(packet_event);
105 } else if (type == PACKET_RETRANSMITTED) {
106 // We only measure network latency using packets that doesn't have to be
107 // retransmitted as there is precisely one sent-receive timestamp pairs.
108 ErasePacketSentTime(packet_event);
109 }
110
111 if (IsReceiverEvent(type))
112 UpdateLastResponseTime(packet_event.timestamp);
113 }
114
GetStats() const115 scoped_ptr<base::DictionaryValue> StatsEventSubscriber::GetStats() const {
116 StatsMap stats_map;
117 GetStatsInternal(&stats_map);
118 scoped_ptr<base::DictionaryValue> ret(new base::DictionaryValue);
119
120 scoped_ptr<base::DictionaryValue> stats(new base::DictionaryValue);
121 for (StatsMap::const_iterator it = stats_map.begin(); it != stats_map.end();
122 ++it) {
123 stats->SetDouble(CastStatToString(it->first), it->second);
124 }
125
126 ret->Set(event_media_type_ == AUDIO_EVENT ? "audio" : "video",
127 stats.release());
128
129 return ret.Pass();
130 }
131
Reset()132 void StatsEventSubscriber::Reset() {
133 DCHECK(thread_checker_.CalledOnValidThread());
134
135 frame_stats_.clear();
136 packet_stats_.clear();
137 total_network_latency_ = base::TimeDelta();
138 network_latency_datapoints_ = 0;
139 total_e2e_latency_ = base::TimeDelta();
140 e2e_latency_datapoints_ = 0;
141 frame_captured_times_.clear();
142 packet_sent_times_.clear();
143 start_time_ = clock_->NowTicks();
144 last_response_received_time_ = base::TimeTicks();
145 }
146
147 // static
CastStatToString(CastStat stat)148 const char* StatsEventSubscriber::CastStatToString(CastStat stat) {
149 switch (stat) {
150 STAT_ENUM_TO_STRING(CAPTURE_FPS);
151 STAT_ENUM_TO_STRING(ENCODE_FPS);
152 STAT_ENUM_TO_STRING(DECODE_FPS);
153 STAT_ENUM_TO_STRING(AVG_ENCODE_TIME_MS);
154 STAT_ENUM_TO_STRING(AVG_PLAYOUT_DELAY_MS);
155 STAT_ENUM_TO_STRING(AVG_NETWORK_LATENCY_MS);
156 STAT_ENUM_TO_STRING(AVG_E2E_LATENCY_MS);
157 STAT_ENUM_TO_STRING(ENCODE_KBPS);
158 STAT_ENUM_TO_STRING(TRANSMISSION_KBPS);
159 STAT_ENUM_TO_STRING(RETRANSMISSION_KBPS);
160 STAT_ENUM_TO_STRING(PACKET_LOSS_FRACTION);
161 STAT_ENUM_TO_STRING(MS_SINCE_LAST_RECEIVER_RESPONSE);
162 }
163 NOTREACHED();
164 return "";
165 }
166
GetStatsInternal(StatsMap * stats_map) const167 void StatsEventSubscriber::GetStatsInternal(StatsMap* stats_map) const {
168 DCHECK(thread_checker_.CalledOnValidThread());
169
170 stats_map->clear();
171
172 base::TimeTicks end_time = clock_->NowTicks();
173
174 PopulateFpsStat(
175 end_time, FRAME_CAPTURE_BEGIN, CAPTURE_FPS, stats_map);
176 PopulateFpsStat(
177 end_time, FRAME_ENCODED, ENCODE_FPS, stats_map);
178 PopulateFpsStat(
179 end_time, FRAME_DECODED, DECODE_FPS, stats_map);
180 PopulatePlayoutDelayStat(stats_map);
181 PopulateFrameBitrateStat(end_time, stats_map);
182 PopulatePacketBitrateStat(end_time,
183 PACKET_SENT_TO_NETWORK,
184 TRANSMISSION_KBPS,
185 stats_map);
186 PopulatePacketBitrateStat(end_time,
187 PACKET_RETRANSMITTED,
188 RETRANSMISSION_KBPS,
189 stats_map);
190 PopulatePacketLossPercentageStat(stats_map);
191
192 if (network_latency_datapoints_ > 0) {
193 double avg_network_latency_ms =
194 total_network_latency_.InMillisecondsF() /
195 network_latency_datapoints_;
196 stats_map->insert(
197 std::make_pair(AVG_NETWORK_LATENCY_MS, avg_network_latency_ms));
198 }
199
200 if (e2e_latency_datapoints_ > 0) {
201 double avg_e2e_latency_ms =
202 total_e2e_latency_.InMillisecondsF() / e2e_latency_datapoints_;
203 stats_map->insert(std::make_pair(AVG_E2E_LATENCY_MS, avg_e2e_latency_ms));
204 }
205
206 if (!last_response_received_time_.is_null()) {
207 stats_map->insert(
208 std::make_pair(MS_SINCE_LAST_RECEIVER_RESPONSE,
209 (end_time - last_response_received_time_).InMillisecondsF()));
210 }
211 }
212
GetReceiverOffset(base::TimeDelta * offset)213 bool StatsEventSubscriber::GetReceiverOffset(base::TimeDelta* offset) {
214 base::TimeDelta receiver_offset_lower_bound;
215 base::TimeDelta receiver_offset_upper_bound;
216 if (!offset_estimator_->GetReceiverOffsetBounds(
217 &receiver_offset_lower_bound, &receiver_offset_upper_bound)) {
218 return false;
219 }
220
221 *offset = (receiver_offset_lower_bound + receiver_offset_upper_bound) / 2;
222 return true;
223 }
224
RecordFrameCapturedTime(const FrameEvent & frame_event)225 void StatsEventSubscriber::RecordFrameCapturedTime(
226 const FrameEvent& frame_event) {
227 frame_captured_times_.insert(
228 std::make_pair(frame_event.rtp_timestamp, frame_event.timestamp));
229 if (frame_captured_times_.size() > kMaxFrameEventTimeMapSize)
230 frame_captured_times_.erase(frame_captured_times_.begin());
231 }
232
RecordE2ELatency(const FrameEvent & frame_event)233 void StatsEventSubscriber::RecordE2ELatency(const FrameEvent& frame_event) {
234 base::TimeDelta receiver_offset;
235 if (!GetReceiverOffset(&receiver_offset))
236 return;
237
238 FrameEventTimeMap::iterator it =
239 frame_captured_times_.find(frame_event.rtp_timestamp);
240 if (it == frame_captured_times_.end())
241 return;
242
243 // Playout time is event time + playout delay.
244 base::TimeTicks playout_time =
245 frame_event.timestamp + frame_event.delay_delta - receiver_offset;
246 total_e2e_latency_ += playout_time - it->second;
247 e2e_latency_datapoints_++;
248 }
249
UpdateLastResponseTime(base::TimeTicks receiver_time)250 void StatsEventSubscriber::UpdateLastResponseTime(
251 base::TimeTicks receiver_time) {
252 base::TimeDelta receiver_offset;
253 if (!GetReceiverOffset(&receiver_offset))
254 return;
255 base::TimeTicks sender_time = receiver_time - receiver_offset;
256 last_response_received_time_ = sender_time;
257 }
258
ErasePacketSentTime(const PacketEvent & packet_event)259 void StatsEventSubscriber::ErasePacketSentTime(
260 const PacketEvent& packet_event) {
261 std::pair<RtpTimestamp, uint16> key(
262 std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
263 packet_sent_times_.erase(key);
264 }
265
RecordNetworkLatency(const PacketEvent & packet_event)266 void StatsEventSubscriber::RecordNetworkLatency(
267 const PacketEvent& packet_event) {
268 base::TimeDelta receiver_offset;
269 if (!GetReceiverOffset(&receiver_offset))
270 return;
271
272 std::pair<RtpTimestamp, uint16> key(
273 std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
274 PacketEventTimeMap::iterator it = packet_sent_times_.find(key);
275 if (it == packet_sent_times_.end()) {
276 std::pair<RtpTimestamp, uint16> key(
277 std::make_pair(packet_event.rtp_timestamp, packet_event.packet_id));
278 std::pair<base::TimeTicks, CastLoggingEvent> value =
279 std::make_pair(packet_event.timestamp, packet_event.type);
280 packet_sent_times_.insert(std::make_pair(key, value));
281 if (packet_sent_times_.size() > kMaxPacketEventTimeMapSize)
282 packet_sent_times_.erase(packet_sent_times_.begin());
283 } else {
284 std::pair<base::TimeTicks, CastLoggingEvent> value = it->second;
285 CastLoggingEvent recorded_type = value.second;
286 bool match = false;
287 base::TimeTicks packet_sent_time;
288 base::TimeTicks packet_received_time;
289 if (recorded_type == PACKET_SENT_TO_NETWORK &&
290 packet_event.type == PACKET_RECEIVED) {
291 packet_sent_time = value.first;
292 packet_received_time = packet_event.timestamp;
293 match = true;
294 } else if (recorded_type == PACKET_RECEIVED &&
295 packet_event.type == PACKET_SENT_TO_NETWORK) {
296 packet_sent_time = packet_event.timestamp;
297 packet_received_time = value.first;
298 match = true;
299 }
300 if (match) {
301 // Subtract by offset.
302 packet_received_time -= receiver_offset;
303
304 total_network_latency_ += packet_received_time - packet_sent_time;
305 network_latency_datapoints_++;
306 packet_sent_times_.erase(it);
307 }
308 }
309 }
310
PopulateFpsStat(base::TimeTicks end_time,CastLoggingEvent event,CastStat stat,StatsMap * stats_map) const311 void StatsEventSubscriber::PopulateFpsStat(base::TimeTicks end_time,
312 CastLoggingEvent event,
313 CastStat stat,
314 StatsMap* stats_map) const {
315 FrameStatsMap::const_iterator it = frame_stats_.find(event);
316 if (it != frame_stats_.end()) {
317 double fps = 0.0;
318 base::TimeDelta duration = (end_time - start_time_);
319 int count = it->second.event_counter;
320 if (duration > base::TimeDelta())
321 fps = count / duration.InSecondsF();
322 stats_map->insert(std::make_pair(stat, fps));
323 }
324 }
325
PopulatePlayoutDelayStat(StatsMap * stats_map) const326 void StatsEventSubscriber::PopulatePlayoutDelayStat(StatsMap* stats_map) const {
327 FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_PLAYOUT);
328 if (it != frame_stats_.end()) {
329 double avg_delay_ms = 0.0;
330 base::TimeDelta sum_delay = it->second.sum_delay;
331 int count = it->second.event_counter;
332 if (count != 0)
333 avg_delay_ms = sum_delay.InMillisecondsF() / count;
334 stats_map->insert(std::make_pair(AVG_PLAYOUT_DELAY_MS, avg_delay_ms));
335 }
336 }
337
PopulateFrameBitrateStat(base::TimeTicks end_time,StatsMap * stats_map) const338 void StatsEventSubscriber::PopulateFrameBitrateStat(base::TimeTicks end_time,
339 StatsMap* stats_map) const {
340 FrameStatsMap::const_iterator it = frame_stats_.find(FRAME_ENCODED);
341 if (it != frame_stats_.end()) {
342 double kbps = 0.0;
343 base::TimeDelta duration = end_time - start_time_;
344 if (duration > base::TimeDelta()) {
345 kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
346 }
347
348 stats_map->insert(std::make_pair(ENCODE_KBPS, kbps));
349 }
350 }
351
PopulatePacketBitrateStat(base::TimeTicks end_time,CastLoggingEvent event,CastStat stat,StatsMap * stats_map) const352 void StatsEventSubscriber::PopulatePacketBitrateStat(
353 base::TimeTicks end_time,
354 CastLoggingEvent event,
355 CastStat stat,
356 StatsMap* stats_map) const {
357 PacketStatsMap::const_iterator it = packet_stats_.find(event);
358 if (it != packet_stats_.end()) {
359 double kbps = 0;
360 base::TimeDelta duration = end_time - start_time_;
361 if (duration > base::TimeDelta()) {
362 kbps = it->second.sum_size / duration.InMillisecondsF() * 8;
363 }
364
365 stats_map->insert(std::make_pair(stat, kbps));
366 }
367 }
368
PopulatePacketLossPercentageStat(StatsMap * stats_map) const369 void StatsEventSubscriber::PopulatePacketLossPercentageStat(
370 StatsMap* stats_map) const {
371 // We assume that retransmission means that the packet's previous
372 // (re)transmission was lost.
373 // This means the percentage of packet loss is
374 // (# of retransmit events) / (# of transmit + retransmit events).
375 PacketStatsMap::const_iterator sent_it =
376 packet_stats_.find(PACKET_SENT_TO_NETWORK);
377 if (sent_it == packet_stats_.end())
378 return;
379 PacketStatsMap::const_iterator retransmitted_it =
380 packet_stats_.find(PACKET_RETRANSMITTED);
381 int sent_count = sent_it->second.event_counter;
382 int retransmitted_count = 0;
383 if (retransmitted_it != packet_stats_.end())
384 retransmitted_count = retransmitted_it->second.event_counter;
385 double packet_loss_fraction = static_cast<double>(retransmitted_count) /
386 (sent_count + retransmitted_count);
387 stats_map->insert(
388 std::make_pair(PACKET_LOSS_FRACTION, packet_loss_fraction));
389 }
390
FrameLogStats()391 StatsEventSubscriber::FrameLogStats::FrameLogStats()
392 : event_counter(0), sum_size(0) {}
~FrameLogStats()393 StatsEventSubscriber::FrameLogStats::~FrameLogStats() {}
394
PacketLogStats()395 StatsEventSubscriber::PacketLogStats::PacketLogStats()
396 : event_counter(0), sum_size(0) {}
~PacketLogStats()397 StatsEventSubscriber::PacketLogStats::~PacketLogStats() {}
398
399 } // namespace cast
400 } // namespace media
401