1 /*
2 * Copyright (c) 2013 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11 #include "video/receive_statistics_proxy.h"
12
13 #include <algorithm>
14 #include <cmath>
15 #include <utility>
16
17 #include "modules/video_coding/include/video_codec_interface.h"
18 #include "rtc_base/checks.h"
19 #include "rtc_base/logging.h"
20 #include "rtc_base/strings/string_builder.h"
21 #include "rtc_base/time_utils.h"
22 #include "system_wrappers/include/clock.h"
23 #include "system_wrappers/include/field_trial.h"
24 #include "system_wrappers/include/metrics.h"
25
26 namespace webrtc {
27 namespace {
28 // Periodic time interval for processing samples for |freq_offset_counter_|.
29 const int64_t kFreqOffsetProcessIntervalMs = 40000;
30
31 // Configuration for bad call detection.
32 const int kBadCallMinRequiredSamples = 10;
33 const int kMinSampleLengthMs = 990;
34 const int kNumMeasurements = 10;
35 const int kNumMeasurementsVariance = kNumMeasurements * 1.5;
36 const float kBadFraction = 0.8f;
37 // For fps:
38 // Low means low enough to be bad, high means high enough to be good
39 const int kLowFpsThreshold = 12;
40 const int kHighFpsThreshold = 14;
41 // For qp and fps variance:
42 // Low means low enough to be good, high means high enough to be bad
43 const int kLowQpThresholdVp8 = 60;
44 const int kHighQpThresholdVp8 = 70;
45 const int kLowVarianceThreshold = 1;
46 const int kHighVarianceThreshold = 2;
47
48 // Some metrics are reported as a maximum over this period.
49 // This should be synchronized with a typical getStats polling interval in
50 // the clients.
51 const int kMovingMaxWindowMs = 1000;
52
53 // How large window we use to calculate the framerate/bitrate.
54 const int kRateStatisticsWindowSizeMs = 1000;
55
56 // Some sane ballpark estimate for maximum common value of inter-frame delay.
57 // Values below that will be stored explicitly in the array,
58 // values above - in the map.
59 const int kMaxCommonInterframeDelayMs = 500;
60
UmaPrefixForContentType(VideoContentType content_type)61 const char* UmaPrefixForContentType(VideoContentType content_type) {
62 if (videocontenttypehelpers::IsScreenshare(content_type))
63 return "WebRTC.Video.Screenshare";
64 return "WebRTC.Video";
65 }
66
UmaSuffixForContentType(VideoContentType content_type)67 std::string UmaSuffixForContentType(VideoContentType content_type) {
68 char ss_buf[1024];
69 rtc::SimpleStringBuilder ss(ss_buf);
70 int simulcast_id = videocontenttypehelpers::GetSimulcastId(content_type);
71 if (simulcast_id > 0) {
72 ss << ".S" << simulcast_id - 1;
73 }
74 int experiment_id = videocontenttypehelpers::GetExperimentId(content_type);
75 if (experiment_id > 0) {
76 ss << ".ExperimentGroup" << experiment_id - 1;
77 }
78 return ss.str();
79 }
80
81 } // namespace
82
ReceiveStatisticsProxy(const VideoReceiveStream::Config * config,Clock * clock)83 ReceiveStatisticsProxy::ReceiveStatisticsProxy(
84 const VideoReceiveStream::Config* config,
85 Clock* clock)
86 : clock_(clock),
87 config_(*config),
88 start_ms_(clock->TimeInMilliseconds()),
89 enable_decode_time_histograms_(
90 !field_trial::IsEnabled("WebRTC-DecodeTimeHistogramsKillSwitch")),
91 last_sample_time_(clock->TimeInMilliseconds()),
92 fps_threshold_(kLowFpsThreshold,
93 kHighFpsThreshold,
94 kBadFraction,
95 kNumMeasurements),
96 qp_threshold_(kLowQpThresholdVp8,
97 kHighQpThresholdVp8,
98 kBadFraction,
99 kNumMeasurements),
100 variance_threshold_(kLowVarianceThreshold,
101 kHighVarianceThreshold,
102 kBadFraction,
103 kNumMeasurementsVariance),
104 num_bad_states_(0),
105 num_certain_states_(0),
106 // 1000ms window, scale 1000 for ms to s.
107 decode_fps_estimator_(1000, 1000),
108 renders_fps_estimator_(1000, 1000),
109 render_fps_tracker_(100, 10u),
110 render_pixel_tracker_(100, 10u),
111 video_quality_observer_(
112 new VideoQualityObserver(VideoContentType::UNSPECIFIED)),
113 interframe_delay_max_moving_(kMovingMaxWindowMs),
114 freq_offset_counter_(clock, nullptr, kFreqOffsetProcessIntervalMs),
115 avg_rtt_ms_(0),
116 last_content_type_(VideoContentType::UNSPECIFIED),
117 last_codec_type_(kVideoCodecVP8),
118 num_delayed_frames_rendered_(0),
119 sum_missed_render_deadline_ms_(0),
120 timing_frame_info_counter_(kMovingMaxWindowMs) {
121 decode_thread_.Detach();
122 network_thread_.Detach();
123 stats_.ssrc = config_.rtp.remote_ssrc;
124 }
125
UpdateHistograms(absl::optional<int> fraction_lost,const StreamDataCounters & rtp_stats,const StreamDataCounters * rtx_stats)126 void ReceiveStatisticsProxy::UpdateHistograms(
127 absl::optional<int> fraction_lost,
128 const StreamDataCounters& rtp_stats,
129 const StreamDataCounters* rtx_stats) {
130 // Not actually running on the decoder thread, but must be called after
131 // DecoderThreadStopped, which detaches the thread checker. It is therefore
132 // safe to access |qp_counters_|, which were updated on the decode thread
133 // earlier.
134 RTC_DCHECK_RUN_ON(&decode_thread_);
135
136 MutexLock lock(&mutex_);
137
138 char log_stream_buf[8 * 1024];
139 rtc::SimpleStringBuilder log_stream(log_stream_buf);
140 int stream_duration_sec = (clock_->TimeInMilliseconds() - start_ms_) / 1000;
141 if (stats_.frame_counts.key_frames > 0 ||
142 stats_.frame_counts.delta_frames > 0) {
143 RTC_HISTOGRAM_COUNTS_100000("WebRTC.Video.ReceiveStreamLifetimeInSeconds",
144 stream_duration_sec);
145 log_stream << "WebRTC.Video.ReceiveStreamLifetimeInSeconds "
146 << stream_duration_sec << '\n';
147 }
148
149 log_stream << "Frames decoded " << stats_.frames_decoded << '\n';
150
151 if (num_unique_frames_) {
152 int num_dropped_frames = *num_unique_frames_ - stats_.frames_decoded;
153 RTC_HISTOGRAM_COUNTS_1000("WebRTC.Video.DroppedFrames.Receiver",
154 num_dropped_frames);
155 log_stream << "WebRTC.Video.DroppedFrames.Receiver " << num_dropped_frames
156 << '\n';
157 }
158
159 if (fraction_lost && stream_duration_sec >= metrics::kMinRunTimeInSeconds) {
160 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.ReceivedPacketsLostInPercent",
161 *fraction_lost);
162 log_stream << "WebRTC.Video.ReceivedPacketsLostInPercent " << *fraction_lost
163 << '\n';
164 }
165
166 if (first_decoded_frame_time_ms_) {
167 const int64_t elapsed_ms =
168 (clock_->TimeInMilliseconds() - *first_decoded_frame_time_ms_);
169 if (elapsed_ms >=
170 metrics::kMinRunTimeInSeconds * rtc::kNumMillisecsPerSec) {
171 int decoded_fps = static_cast<int>(
172 (stats_.frames_decoded * 1000.0f / elapsed_ms) + 0.5f);
173 RTC_HISTOGRAM_COUNTS_100("WebRTC.Video.DecodedFramesPerSecond",
174 decoded_fps);
175 log_stream << "WebRTC.Video.DecodedFramesPerSecond " << decoded_fps
176 << '\n';
177
178 const uint32_t frames_rendered = stats_.frames_rendered;
179 if (frames_rendered > 0) {
180 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.DelayedFramesToRenderer",
181 static_cast<int>(num_delayed_frames_rendered_ *
182 100 / frames_rendered));
183 if (num_delayed_frames_rendered_ > 0) {
184 RTC_HISTOGRAM_COUNTS_1000(
185 "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs",
186 static_cast<int>(sum_missed_render_deadline_ms_ /
187 num_delayed_frames_rendered_));
188 }
189 }
190 }
191 }
192
193 const int kMinRequiredSamples = 200;
194 int samples = static_cast<int>(render_fps_tracker_.TotalSampleCount());
195 if (samples >= kMinRequiredSamples) {
196 int rendered_fps = round(render_fps_tracker_.ComputeTotalRate());
197 RTC_HISTOGRAM_COUNTS_100("WebRTC.Video.RenderFramesPerSecond",
198 rendered_fps);
199 log_stream << "WebRTC.Video.RenderFramesPerSecond " << rendered_fps << '\n';
200 RTC_HISTOGRAM_COUNTS_100000(
201 "WebRTC.Video.RenderSqrtPixelsPerSecond",
202 round(render_pixel_tracker_.ComputeTotalRate()));
203 }
204
205 absl::optional<int> sync_offset_ms =
206 sync_offset_counter_.Avg(kMinRequiredSamples);
207 if (sync_offset_ms) {
208 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.AVSyncOffsetInMs",
209 *sync_offset_ms);
210 log_stream << "WebRTC.Video.AVSyncOffsetInMs " << *sync_offset_ms << '\n';
211 }
212 AggregatedStats freq_offset_stats = freq_offset_counter_.GetStats();
213 if (freq_offset_stats.num_samples > 0) {
214 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.RtpToNtpFreqOffsetInKhz",
215 freq_offset_stats.average);
216 log_stream << "WebRTC.Video.RtpToNtpFreqOffsetInKhz "
217 << freq_offset_stats.ToString() << '\n';
218 }
219
220 int num_total_frames =
221 stats_.frame_counts.key_frames + stats_.frame_counts.delta_frames;
222 if (num_total_frames >= kMinRequiredSamples) {
223 int num_key_frames = stats_.frame_counts.key_frames;
224 int key_frames_permille =
225 (num_key_frames * 1000 + num_total_frames / 2) / num_total_frames;
226 RTC_HISTOGRAM_COUNTS_1000("WebRTC.Video.KeyFramesReceivedInPermille",
227 key_frames_permille);
228 log_stream << "WebRTC.Video.KeyFramesReceivedInPermille "
229 << key_frames_permille << '\n';
230 }
231
232 absl::optional<int> qp = qp_counters_.vp8.Avg(kMinRequiredSamples);
233 if (qp) {
234 RTC_HISTOGRAM_COUNTS_200("WebRTC.Video.Decoded.Vp8.Qp", *qp);
235 log_stream << "WebRTC.Video.Decoded.Vp8.Qp " << *qp << '\n';
236 }
237 absl::optional<int> decode_ms = decode_time_counter_.Avg(kMinRequiredSamples);
238 if (decode_ms) {
239 RTC_HISTOGRAM_COUNTS_1000("WebRTC.Video.DecodeTimeInMs", *decode_ms);
240 log_stream << "WebRTC.Video.DecodeTimeInMs " << *decode_ms << '\n';
241 }
242 absl::optional<int> jb_delay_ms =
243 jitter_buffer_delay_counter_.Avg(kMinRequiredSamples);
244 if (jb_delay_ms) {
245 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.JitterBufferDelayInMs",
246 *jb_delay_ms);
247 log_stream << "WebRTC.Video.JitterBufferDelayInMs " << *jb_delay_ms << '\n';
248 }
249
250 absl::optional<int> target_delay_ms =
251 target_delay_counter_.Avg(kMinRequiredSamples);
252 if (target_delay_ms) {
253 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.TargetDelayInMs",
254 *target_delay_ms);
255 log_stream << "WebRTC.Video.TargetDelayInMs " << *target_delay_ms << '\n';
256 }
257 absl::optional<int> current_delay_ms =
258 current_delay_counter_.Avg(kMinRequiredSamples);
259 if (current_delay_ms) {
260 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.CurrentDelayInMs",
261 *current_delay_ms);
262 log_stream << "WebRTC.Video.CurrentDelayInMs " << *current_delay_ms << '\n';
263 }
264 absl::optional<int> delay_ms = delay_counter_.Avg(kMinRequiredSamples);
265 if (delay_ms)
266 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.OnewayDelayInMs", *delay_ms);
267
268 // Aggregate content_specific_stats_ by removing experiment or simulcast
269 // information;
270 std::map<VideoContentType, ContentSpecificStats> aggregated_stats;
271 for (const auto& it : content_specific_stats_) {
272 // Calculate simulcast specific metrics (".S0" ... ".S2" suffixes).
273 VideoContentType content_type = it.first;
274 if (videocontenttypehelpers::GetSimulcastId(content_type) > 0) {
275 // Aggregate on experiment id.
276 videocontenttypehelpers::SetExperimentId(&content_type, 0);
277 aggregated_stats[content_type].Add(it.second);
278 }
279 // Calculate experiment specific metrics (".ExperimentGroup[0-7]" suffixes).
280 content_type = it.first;
281 if (videocontenttypehelpers::GetExperimentId(content_type) > 0) {
282 // Aggregate on simulcast id.
283 videocontenttypehelpers::SetSimulcastId(&content_type, 0);
284 aggregated_stats[content_type].Add(it.second);
285 }
286 // Calculate aggregated metrics (no suffixes. Aggregated on everything).
287 content_type = it.first;
288 videocontenttypehelpers::SetSimulcastId(&content_type, 0);
289 videocontenttypehelpers::SetExperimentId(&content_type, 0);
290 aggregated_stats[content_type].Add(it.second);
291 }
292
293 for (const auto& it : aggregated_stats) {
294 // For the metric Foo we report the following slices:
295 // WebRTC.Video.Foo,
296 // WebRTC.Video.Screenshare.Foo,
297 // WebRTC.Video.Foo.S[0-3],
298 // WebRTC.Video.Foo.ExperimentGroup[0-7],
299 // WebRTC.Video.Screenshare.Foo.S[0-3],
300 // WebRTC.Video.Screenshare.Foo.ExperimentGroup[0-7].
301 auto content_type = it.first;
302 auto stats = it.second;
303 std::string uma_prefix = UmaPrefixForContentType(content_type);
304 std::string uma_suffix = UmaSuffixForContentType(content_type);
305 // Metrics can be sliced on either simulcast id or experiment id but not
306 // both.
307 RTC_DCHECK(videocontenttypehelpers::GetExperimentId(content_type) == 0 ||
308 videocontenttypehelpers::GetSimulcastId(content_type) == 0);
309
310 absl::optional<int> e2e_delay_ms =
311 stats.e2e_delay_counter.Avg(kMinRequiredSamples);
312 if (e2e_delay_ms) {
313 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
314 uma_prefix + ".EndToEndDelayInMs" + uma_suffix, *e2e_delay_ms);
315 log_stream << uma_prefix << ".EndToEndDelayInMs" << uma_suffix << " "
316 << *e2e_delay_ms << '\n';
317 }
318 absl::optional<int> e2e_delay_max_ms = stats.e2e_delay_counter.Max();
319 if (e2e_delay_max_ms && e2e_delay_ms) {
320 RTC_HISTOGRAM_COUNTS_SPARSE_100000(
321 uma_prefix + ".EndToEndDelayMaxInMs" + uma_suffix, *e2e_delay_max_ms);
322 log_stream << uma_prefix << ".EndToEndDelayMaxInMs" << uma_suffix << " "
323 << *e2e_delay_max_ms << '\n';
324 }
325 absl::optional<int> interframe_delay_ms =
326 stats.interframe_delay_counter.Avg(kMinRequiredSamples);
327 if (interframe_delay_ms) {
328 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
329 uma_prefix + ".InterframeDelayInMs" + uma_suffix,
330 *interframe_delay_ms);
331 log_stream << uma_prefix << ".InterframeDelayInMs" << uma_suffix << " "
332 << *interframe_delay_ms << '\n';
333 }
334 absl::optional<int> interframe_delay_max_ms =
335 stats.interframe_delay_counter.Max();
336 if (interframe_delay_max_ms && interframe_delay_ms) {
337 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
338 uma_prefix + ".InterframeDelayMaxInMs" + uma_suffix,
339 *interframe_delay_max_ms);
340 log_stream << uma_prefix << ".InterframeDelayMaxInMs" << uma_suffix << " "
341 << *interframe_delay_max_ms << '\n';
342 }
343
344 absl::optional<uint32_t> interframe_delay_95p_ms =
345 stats.interframe_delay_percentiles.GetPercentile(0.95f);
346 if (interframe_delay_95p_ms && interframe_delay_ms != -1) {
347 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
348 uma_prefix + ".InterframeDelay95PercentileInMs" + uma_suffix,
349 *interframe_delay_95p_ms);
350 log_stream << uma_prefix << ".InterframeDelay95PercentileInMs"
351 << uma_suffix << " " << *interframe_delay_95p_ms << '\n';
352 }
353
354 absl::optional<int> width = stats.received_width.Avg(kMinRequiredSamples);
355 if (width) {
356 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
357 uma_prefix + ".ReceivedWidthInPixels" + uma_suffix, *width);
358 log_stream << uma_prefix << ".ReceivedWidthInPixels" << uma_suffix << " "
359 << *width << '\n';
360 }
361
362 absl::optional<int> height = stats.received_height.Avg(kMinRequiredSamples);
363 if (height) {
364 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
365 uma_prefix + ".ReceivedHeightInPixels" + uma_suffix, *height);
366 log_stream << uma_prefix << ".ReceivedHeightInPixels" << uma_suffix << " "
367 << *height << '\n';
368 }
369
370 if (content_type != VideoContentType::UNSPECIFIED) {
371 // Don't report these 3 metrics unsliced, as more precise variants
372 // are reported separately in this method.
373 float flow_duration_sec = stats.flow_duration_ms / 1000.0;
374 if (flow_duration_sec >= metrics::kMinRunTimeInSeconds) {
375 int media_bitrate_kbps = static_cast<int>(stats.total_media_bytes * 8 /
376 flow_duration_sec / 1000);
377 RTC_HISTOGRAM_COUNTS_SPARSE_10000(
378 uma_prefix + ".MediaBitrateReceivedInKbps" + uma_suffix,
379 media_bitrate_kbps);
380 log_stream << uma_prefix << ".MediaBitrateReceivedInKbps" << uma_suffix
381 << " " << media_bitrate_kbps << '\n';
382 }
383
384 int num_total_frames =
385 stats.frame_counts.key_frames + stats.frame_counts.delta_frames;
386 if (num_total_frames >= kMinRequiredSamples) {
387 int num_key_frames = stats.frame_counts.key_frames;
388 int key_frames_permille =
389 (num_key_frames * 1000 + num_total_frames / 2) / num_total_frames;
390 RTC_HISTOGRAM_COUNTS_SPARSE_1000(
391 uma_prefix + ".KeyFramesReceivedInPermille" + uma_suffix,
392 key_frames_permille);
393 log_stream << uma_prefix << ".KeyFramesReceivedInPermille" << uma_suffix
394 << " " << key_frames_permille << '\n';
395 }
396
397 absl::optional<int> qp = stats.qp_counter.Avg(kMinRequiredSamples);
398 if (qp) {
399 RTC_HISTOGRAM_COUNTS_SPARSE_200(
400 uma_prefix + ".Decoded.Vp8.Qp" + uma_suffix, *qp);
401 log_stream << uma_prefix << ".Decoded.Vp8.Qp" << uma_suffix << " "
402 << *qp << '\n';
403 }
404 }
405 }
406
407 StreamDataCounters rtp_rtx_stats = rtp_stats;
408 if (rtx_stats)
409 rtp_rtx_stats.Add(*rtx_stats);
410 int64_t elapsed_sec =
411 rtp_rtx_stats.TimeSinceFirstPacketInMs(clock_->TimeInMilliseconds()) /
412 1000;
413 if (elapsed_sec >= metrics::kMinRunTimeInSeconds) {
414 RTC_HISTOGRAM_COUNTS_10000(
415 "WebRTC.Video.BitrateReceivedInKbps",
416 static_cast<int>(rtp_rtx_stats.transmitted.TotalBytes() * 8 /
417 elapsed_sec / 1000));
418 int media_bitrate_kbs = static_cast<int>(rtp_stats.MediaPayloadBytes() * 8 /
419 elapsed_sec / 1000);
420 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.MediaBitrateReceivedInKbps",
421 media_bitrate_kbs);
422 log_stream << "WebRTC.Video.MediaBitrateReceivedInKbps "
423 << media_bitrate_kbs << '\n';
424 RTC_HISTOGRAM_COUNTS_10000(
425 "WebRTC.Video.PaddingBitrateReceivedInKbps",
426 static_cast<int>(rtp_rtx_stats.transmitted.padding_bytes * 8 /
427 elapsed_sec / 1000));
428 RTC_HISTOGRAM_COUNTS_10000(
429 "WebRTC.Video.RetransmittedBitrateReceivedInKbps",
430 static_cast<int>(rtp_rtx_stats.retransmitted.TotalBytes() * 8 /
431 elapsed_sec / 1000));
432 if (rtx_stats) {
433 RTC_HISTOGRAM_COUNTS_10000(
434 "WebRTC.Video.RtxBitrateReceivedInKbps",
435 static_cast<int>(rtx_stats->transmitted.TotalBytes() * 8 /
436 elapsed_sec / 1000));
437 }
438 const RtcpPacketTypeCounter& counters = stats_.rtcp_packet_type_counts;
439 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.NackPacketsSentPerMinute",
440 counters.nack_packets * 60 / elapsed_sec);
441 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.FirPacketsSentPerMinute",
442 counters.fir_packets * 60 / elapsed_sec);
443 RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.PliPacketsSentPerMinute",
444 counters.pli_packets * 60 / elapsed_sec);
445 if (counters.nack_requests > 0) {
446 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.UniqueNackRequestsSentInPercent",
447 counters.UniqueNackRequestsInPercent());
448 }
449 }
450
451 if (num_certain_states_ >= kBadCallMinRequiredSamples) {
452 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.BadCall.Any",
453 100 * num_bad_states_ / num_certain_states_);
454 }
455 absl::optional<double> fps_fraction =
456 fps_threshold_.FractionHigh(kBadCallMinRequiredSamples);
457 if (fps_fraction) {
458 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.BadCall.FrameRate",
459 static_cast<int>(100 * (1 - *fps_fraction)));
460 }
461 absl::optional<double> variance_fraction =
462 variance_threshold_.FractionHigh(kBadCallMinRequiredSamples);
463 if (variance_fraction) {
464 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.BadCall.FrameRateVariance",
465 static_cast<int>(100 * *variance_fraction));
466 }
467 absl::optional<double> qp_fraction =
468 qp_threshold_.FractionHigh(kBadCallMinRequiredSamples);
469 if (qp_fraction) {
470 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.BadCall.Qp",
471 static_cast<int>(100 * *qp_fraction));
472 }
473
474 RTC_LOG(LS_INFO) << log_stream.str();
475 video_quality_observer_->UpdateHistograms();
476 }
477
QualitySample()478 void ReceiveStatisticsProxy::QualitySample() {
479 int64_t now = clock_->TimeInMilliseconds();
480 if (last_sample_time_ + kMinSampleLengthMs > now)
481 return;
482
483 double fps =
484 render_fps_tracker_.ComputeRateForInterval(now - last_sample_time_);
485 absl::optional<int> qp = qp_sample_.Avg(1);
486
487 bool prev_fps_bad = !fps_threshold_.IsHigh().value_or(true);
488 bool prev_qp_bad = qp_threshold_.IsHigh().value_or(false);
489 bool prev_variance_bad = variance_threshold_.IsHigh().value_or(false);
490 bool prev_any_bad = prev_fps_bad || prev_qp_bad || prev_variance_bad;
491
492 fps_threshold_.AddMeasurement(static_cast<int>(fps));
493 if (qp)
494 qp_threshold_.AddMeasurement(*qp);
495 absl::optional<double> fps_variance_opt = fps_threshold_.CalculateVariance();
496 double fps_variance = fps_variance_opt.value_or(0);
497 if (fps_variance_opt) {
498 variance_threshold_.AddMeasurement(static_cast<int>(fps_variance));
499 }
500
501 bool fps_bad = !fps_threshold_.IsHigh().value_or(true);
502 bool qp_bad = qp_threshold_.IsHigh().value_or(false);
503 bool variance_bad = variance_threshold_.IsHigh().value_or(false);
504 bool any_bad = fps_bad || qp_bad || variance_bad;
505
506 if (!prev_any_bad && any_bad) {
507 RTC_LOG(LS_INFO) << "Bad call (any) start: " << now;
508 } else if (prev_any_bad && !any_bad) {
509 RTC_LOG(LS_INFO) << "Bad call (any) end: " << now;
510 }
511
512 if (!prev_fps_bad && fps_bad) {
513 RTC_LOG(LS_INFO) << "Bad call (fps) start: " << now;
514 } else if (prev_fps_bad && !fps_bad) {
515 RTC_LOG(LS_INFO) << "Bad call (fps) end: " << now;
516 }
517
518 if (!prev_qp_bad && qp_bad) {
519 RTC_LOG(LS_INFO) << "Bad call (qp) start: " << now;
520 } else if (prev_qp_bad && !qp_bad) {
521 RTC_LOG(LS_INFO) << "Bad call (qp) end: " << now;
522 }
523
524 if (!prev_variance_bad && variance_bad) {
525 RTC_LOG(LS_INFO) << "Bad call (variance) start: " << now;
526 } else if (prev_variance_bad && !variance_bad) {
527 RTC_LOG(LS_INFO) << "Bad call (variance) end: " << now;
528 }
529
530 RTC_LOG(LS_VERBOSE) << "SAMPLE: sample_length: " << (now - last_sample_time_)
531 << " fps: " << fps << " fps_bad: " << fps_bad
532 << " qp: " << qp.value_or(-1) << " qp_bad: " << qp_bad
533 << " variance_bad: " << variance_bad
534 << " fps_variance: " << fps_variance;
535
536 last_sample_time_ = now;
537 qp_sample_.Reset();
538
539 if (fps_threshold_.IsHigh() || variance_threshold_.IsHigh() ||
540 qp_threshold_.IsHigh()) {
541 if (any_bad)
542 ++num_bad_states_;
543 ++num_certain_states_;
544 }
545 }
546
UpdateFramerate(int64_t now_ms) const547 void ReceiveStatisticsProxy::UpdateFramerate(int64_t now_ms) const {
548 int64_t old_frames_ms = now_ms - kRateStatisticsWindowSizeMs;
549 while (!frame_window_.empty() &&
550 frame_window_.begin()->first < old_frames_ms) {
551 frame_window_.erase(frame_window_.begin());
552 }
553
554 size_t framerate =
555 (frame_window_.size() * 1000 + 500) / kRateStatisticsWindowSizeMs;
556 stats_.network_frame_rate = static_cast<int>(framerate);
557 }
558
UpdateDecodeTimeHistograms(int width,int height,int decode_time_ms) const559 void ReceiveStatisticsProxy::UpdateDecodeTimeHistograms(
560 int width,
561 int height,
562 int decode_time_ms) const {
563 bool is_4k = (width == 3840 || width == 4096) && height == 2160;
564 bool is_hd = width == 1920 && height == 1080;
565 // Only update histograms for 4k/HD and VP9/H264.
566 if ((is_4k || is_hd) && (last_codec_type_ == kVideoCodecVP9 ||
567 last_codec_type_ == kVideoCodecH264)) {
568 const std::string kDecodeTimeUmaPrefix =
569 "WebRTC.Video.DecodeTimePerFrameInMs.";
570
571 // Each histogram needs its own line for it to not be reused in the wrong
572 // way when the format changes.
573 if (last_codec_type_ == kVideoCodecVP9) {
574 bool is_sw_decoder =
575 stats_.decoder_implementation_name.compare(0, 6, "libvpx") == 0;
576 if (is_4k) {
577 if (is_sw_decoder)
578 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "Vp9.4k.Sw",
579 decode_time_ms);
580 else
581 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "Vp9.4k.Hw",
582 decode_time_ms);
583 } else {
584 if (is_sw_decoder)
585 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "Vp9.Hd.Sw",
586 decode_time_ms);
587 else
588 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "Vp9.Hd.Hw",
589 decode_time_ms);
590 }
591 } else {
592 bool is_sw_decoder =
593 stats_.decoder_implementation_name.compare(0, 6, "FFmpeg") == 0;
594 if (is_4k) {
595 if (is_sw_decoder)
596 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "H264.4k.Sw",
597 decode_time_ms);
598 else
599 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "H264.4k.Hw",
600 decode_time_ms);
601
602 } else {
603 if (is_sw_decoder)
604 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "H264.Hd.Sw",
605 decode_time_ms);
606 else
607 RTC_HISTOGRAM_COUNTS_1000(kDecodeTimeUmaPrefix + "H264.Hd.Hw",
608 decode_time_ms);
609 }
610 }
611 }
612 }
613
614 absl::optional<int64_t>
GetCurrentEstimatedPlayoutNtpTimestampMs(int64_t now_ms) const615 ReceiveStatisticsProxy::GetCurrentEstimatedPlayoutNtpTimestampMs(
616 int64_t now_ms) const {
617 if (!last_estimated_playout_ntp_timestamp_ms_ ||
618 !last_estimated_playout_time_ms_) {
619 return absl::nullopt;
620 }
621 int64_t elapsed_ms = now_ms - *last_estimated_playout_time_ms_;
622 return *last_estimated_playout_ntp_timestamp_ms_ + elapsed_ms;
623 }
624
GetStats() const625 VideoReceiveStream::Stats ReceiveStatisticsProxy::GetStats() const {
626 MutexLock lock(&mutex_);
627 // Get current frame rates here, as only updating them on new frames prevents
628 // us from ever correctly displaying frame rate of 0.
629 int64_t now_ms = clock_->TimeInMilliseconds();
630 UpdateFramerate(now_ms);
631 stats_.render_frame_rate = renders_fps_estimator_.Rate(now_ms).value_or(0);
632 stats_.decode_frame_rate = decode_fps_estimator_.Rate(now_ms).value_or(0);
633 stats_.interframe_delay_max_ms =
634 interframe_delay_max_moving_.Max(now_ms).value_or(-1);
635 stats_.freeze_count = video_quality_observer_->NumFreezes();
636 stats_.pause_count = video_quality_observer_->NumPauses();
637 stats_.total_freezes_duration_ms =
638 video_quality_observer_->TotalFreezesDurationMs();
639 stats_.total_pauses_duration_ms =
640 video_quality_observer_->TotalPausesDurationMs();
641 stats_.total_frames_duration_ms =
642 video_quality_observer_->TotalFramesDurationMs();
643 stats_.sum_squared_frame_durations =
644 video_quality_observer_->SumSquaredFrameDurationsSec();
645 stats_.content_type = last_content_type_;
646 stats_.timing_frame_info = timing_frame_info_counter_.Max(now_ms);
647 stats_.jitter_buffer_delay_seconds =
648 static_cast<double>(current_delay_counter_.Sum(1).value_or(0)) /
649 rtc::kNumMillisecsPerSec;
650 stats_.jitter_buffer_emitted_count = current_delay_counter_.NumSamples();
651 stats_.estimated_playout_ntp_timestamp_ms =
652 GetCurrentEstimatedPlayoutNtpTimestampMs(now_ms);
653 return stats_;
654 }
655
OnIncomingPayloadType(int payload_type)656 void ReceiveStatisticsProxy::OnIncomingPayloadType(int payload_type) {
657 MutexLock lock(&mutex_);
658 stats_.current_payload_type = payload_type;
659 }
660
OnDecoderImplementationName(const char * implementation_name)661 void ReceiveStatisticsProxy::OnDecoderImplementationName(
662 const char* implementation_name) {
663 MutexLock lock(&mutex_);
664 stats_.decoder_implementation_name = implementation_name;
665 }
666
OnFrameBufferTimingsUpdated(int max_decode_ms,int current_delay_ms,int target_delay_ms,int jitter_buffer_ms,int min_playout_delay_ms,int render_delay_ms)667 void ReceiveStatisticsProxy::OnFrameBufferTimingsUpdated(
668 int max_decode_ms,
669 int current_delay_ms,
670 int target_delay_ms,
671 int jitter_buffer_ms,
672 int min_playout_delay_ms,
673 int render_delay_ms) {
674 MutexLock lock(&mutex_);
675 stats_.max_decode_ms = max_decode_ms;
676 stats_.current_delay_ms = current_delay_ms;
677 stats_.target_delay_ms = target_delay_ms;
678 stats_.jitter_buffer_ms = jitter_buffer_ms;
679 stats_.min_playout_delay_ms = min_playout_delay_ms;
680 stats_.render_delay_ms = render_delay_ms;
681 jitter_buffer_delay_counter_.Add(jitter_buffer_ms);
682 target_delay_counter_.Add(target_delay_ms);
683 current_delay_counter_.Add(current_delay_ms);
684 // Network delay (rtt/2) + target_delay_ms (jitter delay + decode time +
685 // render delay).
686 delay_counter_.Add(target_delay_ms + avg_rtt_ms_ / 2);
687 }
688
OnUniqueFramesCounted(int num_unique_frames)689 void ReceiveStatisticsProxy::OnUniqueFramesCounted(int num_unique_frames) {
690 MutexLock lock(&mutex_);
691 num_unique_frames_.emplace(num_unique_frames);
692 }
693
OnTimingFrameInfoUpdated(const TimingFrameInfo & info)694 void ReceiveStatisticsProxy::OnTimingFrameInfoUpdated(
695 const TimingFrameInfo& info) {
696 MutexLock lock(&mutex_);
697 if (info.flags != VideoSendTiming::kInvalid) {
698 int64_t now_ms = clock_->TimeInMilliseconds();
699 timing_frame_info_counter_.Add(info, now_ms);
700 }
701
702 // Measure initial decoding latency between the first frame arriving and the
703 // first frame being decoded.
704 if (!first_frame_received_time_ms_.has_value()) {
705 first_frame_received_time_ms_ = info.receive_finish_ms;
706 }
707 if (stats_.first_frame_received_to_decoded_ms == -1 &&
708 first_decoded_frame_time_ms_) {
709 stats_.first_frame_received_to_decoded_ms =
710 *first_decoded_frame_time_ms_ - *first_frame_received_time_ms_;
711 }
712 }
713
RtcpPacketTypesCounterUpdated(uint32_t ssrc,const RtcpPacketTypeCounter & packet_counter)714 void ReceiveStatisticsProxy::RtcpPacketTypesCounterUpdated(
715 uint32_t ssrc,
716 const RtcpPacketTypeCounter& packet_counter) {
717 MutexLock lock(&mutex_);
718 if (stats_.ssrc != ssrc)
719 return;
720 stats_.rtcp_packet_type_counts = packet_counter;
721 }
722
OnCname(uint32_t ssrc,absl::string_view cname)723 void ReceiveStatisticsProxy::OnCname(uint32_t ssrc, absl::string_view cname) {
724 MutexLock lock(&mutex_);
725 // TODO(pbos): Handle both local and remote ssrcs here and RTC_DCHECK that we
726 // receive stats from one of them.
727 if (stats_.ssrc != ssrc)
728 return;
729 stats_.c_name = std::string(cname);
730 }
731
OnDecodedFrame(const VideoFrame & frame,absl::optional<uint8_t> qp,int32_t decode_time_ms,VideoContentType content_type)732 void ReceiveStatisticsProxy::OnDecodedFrame(const VideoFrame& frame,
733 absl::optional<uint8_t> qp,
734 int32_t decode_time_ms,
735 VideoContentType content_type) {
736 MutexLock lock(&mutex_);
737
738 uint64_t now_ms = clock_->TimeInMilliseconds();
739
740 if (videocontenttypehelpers::IsScreenshare(content_type) !=
741 videocontenttypehelpers::IsScreenshare(last_content_type_)) {
742 // Reset the quality observer if content type is switched. But first report
743 // stats for the previous part of the call.
744 video_quality_observer_->UpdateHistograms();
745 video_quality_observer_.reset(new VideoQualityObserver(content_type));
746 }
747
748 video_quality_observer_->OnDecodedFrame(frame, qp, last_codec_type_);
749
750 ContentSpecificStats* content_specific_stats =
751 &content_specific_stats_[content_type];
752 ++stats_.frames_decoded;
753 if (qp) {
754 if (!stats_.qp_sum) {
755 if (stats_.frames_decoded != 1) {
756 RTC_LOG(LS_WARNING)
757 << "Frames decoded was not 1 when first qp value was received.";
758 }
759 stats_.qp_sum = 0;
760 }
761 *stats_.qp_sum += *qp;
762 content_specific_stats->qp_counter.Add(*qp);
763 } else if (stats_.qp_sum) {
764 RTC_LOG(LS_WARNING)
765 << "QP sum was already set and no QP was given for a frame.";
766 stats_.qp_sum.reset();
767 }
768 decode_time_counter_.Add(decode_time_ms);
769 stats_.decode_ms = decode_time_ms;
770 stats_.total_decode_time_ms += decode_time_ms;
771 if (enable_decode_time_histograms_) {
772 UpdateDecodeTimeHistograms(frame.width(), frame.height(), decode_time_ms);
773 }
774
775 last_content_type_ = content_type;
776 decode_fps_estimator_.Update(1, now_ms);
777 if (last_decoded_frame_time_ms_) {
778 int64_t interframe_delay_ms = now_ms - *last_decoded_frame_time_ms_;
779 RTC_DCHECK_GE(interframe_delay_ms, 0);
780 double interframe_delay = interframe_delay_ms / 1000.0;
781 stats_.total_inter_frame_delay += interframe_delay;
782 stats_.total_squared_inter_frame_delay +=
783 interframe_delay * interframe_delay;
784 interframe_delay_max_moving_.Add(interframe_delay_ms, now_ms);
785 content_specific_stats->interframe_delay_counter.Add(interframe_delay_ms);
786 content_specific_stats->interframe_delay_percentiles.Add(
787 interframe_delay_ms);
788 content_specific_stats->flow_duration_ms += interframe_delay_ms;
789 }
790 if (stats_.frames_decoded == 1) {
791 first_decoded_frame_time_ms_.emplace(now_ms);
792 }
793 last_decoded_frame_time_ms_.emplace(now_ms);
794 }
795
OnRenderedFrame(const VideoFrame & frame)796 void ReceiveStatisticsProxy::OnRenderedFrame(const VideoFrame& frame) {
797 int width = frame.width();
798 int height = frame.height();
799 RTC_DCHECK_GT(width, 0);
800 RTC_DCHECK_GT(height, 0);
801 int64_t now_ms = clock_->TimeInMilliseconds();
802 MutexLock lock(&mutex_);
803
804 video_quality_observer_->OnRenderedFrame(frame, now_ms);
805
806 ContentSpecificStats* content_specific_stats =
807 &content_specific_stats_[last_content_type_];
808 renders_fps_estimator_.Update(1, now_ms);
809 ++stats_.frames_rendered;
810 stats_.width = width;
811 stats_.height = height;
812 render_fps_tracker_.AddSamples(1);
813 render_pixel_tracker_.AddSamples(sqrt(width * height));
814 content_specific_stats->received_width.Add(width);
815 content_specific_stats->received_height.Add(height);
816
817 // Consider taking stats_.render_delay_ms into account.
818 const int64_t time_until_rendering_ms = frame.render_time_ms() - now_ms;
819 if (time_until_rendering_ms < 0) {
820 sum_missed_render_deadline_ms_ += -time_until_rendering_ms;
821 ++num_delayed_frames_rendered_;
822 }
823
824 if (frame.ntp_time_ms() > 0) {
825 int64_t delay_ms = clock_->CurrentNtpInMilliseconds() - frame.ntp_time_ms();
826 if (delay_ms >= 0) {
827 content_specific_stats->e2e_delay_counter.Add(delay_ms);
828 }
829 }
830 QualitySample();
831 }
832
OnSyncOffsetUpdated(int64_t video_playout_ntp_ms,int64_t sync_offset_ms,double estimated_freq_khz)833 void ReceiveStatisticsProxy::OnSyncOffsetUpdated(int64_t video_playout_ntp_ms,
834 int64_t sync_offset_ms,
835 double estimated_freq_khz) {
836 MutexLock lock(&mutex_);
837 sync_offset_counter_.Add(std::abs(sync_offset_ms));
838 stats_.sync_offset_ms = sync_offset_ms;
839 last_estimated_playout_ntp_timestamp_ms_ = video_playout_ntp_ms;
840 last_estimated_playout_time_ms_ = clock_->TimeInMilliseconds();
841
842 const double kMaxFreqKhz = 10000.0;
843 int offset_khz = kMaxFreqKhz;
844 // Should not be zero or negative. If so, report max.
845 if (estimated_freq_khz < kMaxFreqKhz && estimated_freq_khz > 0.0)
846 offset_khz = static_cast<int>(std::fabs(estimated_freq_khz - 90.0) + 0.5);
847
848 freq_offset_counter_.Add(offset_khz);
849 }
850
OnCompleteFrame(bool is_keyframe,size_t size_bytes,VideoContentType content_type)851 void ReceiveStatisticsProxy::OnCompleteFrame(bool is_keyframe,
852 size_t size_bytes,
853 VideoContentType content_type) {
854 MutexLock lock(&mutex_);
855 if (is_keyframe) {
856 ++stats_.frame_counts.key_frames;
857 } else {
858 ++stats_.frame_counts.delta_frames;
859 }
860
861 // Content type extension is set only for keyframes and should be propagated
862 // for all the following delta frames. Here we may receive frames out of order
863 // and miscategorise some delta frames near the layer switch.
864 // This may slightly offset calculated bitrate and keyframes permille metrics.
865 VideoContentType propagated_content_type =
866 is_keyframe ? content_type : last_content_type_;
867
868 ContentSpecificStats* content_specific_stats =
869 &content_specific_stats_[propagated_content_type];
870
871 content_specific_stats->total_media_bytes += size_bytes;
872 if (is_keyframe) {
873 ++content_specific_stats->frame_counts.key_frames;
874 } else {
875 ++content_specific_stats->frame_counts.delta_frames;
876 }
877
878 int64_t now_ms = clock_->TimeInMilliseconds();
879 frame_window_.insert(std::make_pair(now_ms, size_bytes));
880 UpdateFramerate(now_ms);
881 }
882
OnDroppedFrames(uint32_t frames_dropped)883 void ReceiveStatisticsProxy::OnDroppedFrames(uint32_t frames_dropped) {
884 MutexLock lock(&mutex_);
885 stats_.frames_dropped += frames_dropped;
886 }
887
OnPreDecode(VideoCodecType codec_type,int qp)888 void ReceiveStatisticsProxy::OnPreDecode(VideoCodecType codec_type, int qp) {
889 RTC_DCHECK_RUN_ON(&decode_thread_);
890 MutexLock lock(&mutex_);
891 last_codec_type_ = codec_type;
892 if (last_codec_type_ == kVideoCodecVP8 && qp != -1) {
893 qp_counters_.vp8.Add(qp);
894 qp_sample_.Add(qp);
895 }
896 }
897
OnStreamInactive()898 void ReceiveStatisticsProxy::OnStreamInactive() {
899 // TODO(sprang): Figure out any other state that should be reset.
900
901 MutexLock lock(&mutex_);
902 // Don't report inter-frame delay if stream was paused.
903 last_decoded_frame_time_ms_.reset();
904 video_quality_observer_->OnStreamInactive();
905 }
906
OnRttUpdate(int64_t avg_rtt_ms,int64_t max_rtt_ms)907 void ReceiveStatisticsProxy::OnRttUpdate(int64_t avg_rtt_ms,
908 int64_t max_rtt_ms) {
909 MutexLock lock(&mutex_);
910 avg_rtt_ms_ = avg_rtt_ms;
911 }
912
DecoderThreadStarting()913 void ReceiveStatisticsProxy::DecoderThreadStarting() {
914 RTC_DCHECK_RUN_ON(&main_thread_);
915 }
916
DecoderThreadStopped()917 void ReceiveStatisticsProxy::DecoderThreadStopped() {
918 RTC_DCHECK_RUN_ON(&main_thread_);
919 decode_thread_.Detach();
920 }
921
ContentSpecificStats()922 ReceiveStatisticsProxy::ContentSpecificStats::ContentSpecificStats()
923 : interframe_delay_percentiles(kMaxCommonInterframeDelayMs) {}
924
925 ReceiveStatisticsProxy::ContentSpecificStats::~ContentSpecificStats() = default;
926
Add(const ContentSpecificStats & other)927 void ReceiveStatisticsProxy::ContentSpecificStats::Add(
928 const ContentSpecificStats& other) {
929 e2e_delay_counter.Add(other.e2e_delay_counter);
930 interframe_delay_counter.Add(other.interframe_delay_counter);
931 flow_duration_ms += other.flow_duration_ms;
932 total_media_bytes += other.total_media_bytes;
933 received_height.Add(other.received_height);
934 received_width.Add(other.received_width);
935 qp_counter.Add(other.qp_counter);
936 frame_counts.key_frames += other.frame_counts.key_frames;
937 frame_counts.delta_frames += other.frame_counts.delta_frames;
938 interframe_delay_percentiles.Add(other.interframe_delay_percentiles);
939 }
940 } // namespace webrtc
941