Logging basic bad call detection

webrtc/video/receive_statistics_proxy.cc

 /*
  *  Copyright (c) 2013 The WebRTC project authors. All Rights Reserved.
  *
  *  Use of this source code is governed by a BSD-style license
  *  that can be found in the LICENSE file in the root of the source
  *  tree. An additional intellectual property rights grant can be found
  *  in the file PATENTS.  All contributing project authors may
  *  be found in the AUTHORS file in the root of the source tree.
  */
 
 #include "webrtc/video/receive_statistics_proxy.h"
 
 #include <cmath>
 
 #include "webrtc/base/checks.h"
+#include "webrtc/base/logging.h"
 #include "webrtc/modules/video_coding/include/video_codec_interface.h"
 #include "webrtc/system_wrappers/include/clock.h"
 #include "webrtc/system_wrappers/include/metrics.h"
 
 namespace webrtc {
 namespace {
 // Periodic time interval for processing samples for |freq_offset_counter_|.
 const int64_t kFreqOffsetProcessIntervalMs = 40000;
+
+// Configuration for bad call detection.
+const int kNumMeasurements = 10;
+const float kBadFraction = 0.8f;
+const int kLowFpsThreshold = 12;
+const int kHighFpsThreshold = 14;
+const int kLowQpThreshold = 60;

[stefan-webrtc, 2016/11/28 15:55:25]

seems like a high threshold to be considered "low". Or does it mean that it's
low enough to not be considered "bad"?

[palmkvist, 2016/12/01 13:03:45]

It means it is low enough to not be considered bad. Should I add a comment or
change the name to clarify?

[stefan-webrtc, 2016/12/02 09:31:55]

Ok, I'd rename it I think. Comment is probably fine too.

+const int kHighQpThreshold = 70;
+const int kNumMeasurementsVariance = kNumMeasurements * 1.5;
+const int kLowVarianceThreshold = 1;
+const int kHighVarianceThreshold = 2;
 }  // namespace
 
 ReceiveStatisticsProxy::ReceiveStatisticsProxy(
     const VideoReceiveStream::Config* config,
     Clock* clock)
     : clock_(clock),
       config_(*config),
       start_ms_(clock->TimeInMilliseconds()),
       // 1000ms window, scale 1000 for ms to s.
+      last_sample_time_(clock->TimeInMilliseconds()),
+      fps_threshold_(kLowFpsThreshold,
+                     kHighFpsThreshold,
+                     kBadFraction,
+                     kNumMeasurements),
+      qp_threshold_(kLowQpThreshold,
+                    kHighQpThreshold,
+                    kBadFraction,
+                    kNumMeasurements),
+      variance_threshold_(kLowVarianceThreshold,
+                          kHighVarianceThreshold,
+                          kBadFraction,
+                          kNumMeasurementsVariance),
       decode_fps_estimator_(1000, 1000),
       renders_fps_estimator_(1000, 1000),
       render_fps_tracker_(100, 10u),
       render_pixel_tracker_(100, 10u),
       freq_offset_counter_(clock, nullptr, kFreqOffsetProcessIntervalMs) {
   stats_.ssrc = config_.rtp.remote_ssrc;
   for (auto it : config_.rtp.rtx)
     rtx_stats_[it.second.ssrc] = StreamDataCounters();
 }
 
@@ skipping 110 matching lines @@
                                counters.fir_packets * 60 / elapsed_sec);
     RTC_HISTOGRAM_COUNTS_10000("WebRTC.Video.PliPacketsSentPerMinute",
                                counters.pli_packets * 60 / elapsed_sec);
     if (counters.nack_requests > 0) {
       RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.UniqueNackRequestsSentInPercent",
                                counters.UniqueNackRequestsInPercent());
     }
   }
 }
 
+void ReceiveStatisticsProxy::QualitySample() {
+  uint64_t now = clock_->TimeInMilliseconds();
+
+  double fps =
+      render_fps_tracker_.ComputeRateForInterval(now - last_sample_time_);
+  int qp = qp_sample_.Avg(1);

[stefan-webrtc, 2016/11/28 15:55:24]

What does 1 mean here?

[palmkvist, 2016/12/01 13:03:45]

It's number of samples required to return an average. The intention is to take
the average qp since the last QualitySample, so as long as there is a single
sample the average is interesting. Should I add a named local variable or
comment for clarity?

[stefan-webrtc, 2016/12/02 09:31:55]

I see. I guess it's fine as is.

+
+  bool prev_fps_bad = !fps_threshold_.IsHigh().value_or(true);
+  bool prev_qp_bad = qp_threshold_.IsHigh().value_or(false);
+  bool prev_variance_bad = variance_threshold_.IsHigh().value_or(false);
+  bool prev_any_bad = prev_fps_bad || prev_qp_bad || prev_variance_bad;
+
+  fps_threshold_.AddMeasurement(static_cast<int>(fps));
+  qp_threshold_.AddMeasurement(qp);
+  rtc::Optional<double> fps_variance_opt = fps_threshold_.CalculateVariance();
+  double fps_variance = fps_variance_opt.value_or(0);
+  if (fps_variance_opt) {
+    variance_threshold_.AddMeasurement(static_cast<int>(fps_variance));
+  }
+
+  bool fps_bad = !fps_threshold_.IsHigh().value_or(true);
+  bool qp_bad = qp_threshold_.IsHigh().value_or(false);
+  bool variance_bad = variance_threshold_.IsHigh().value_or(false);
+  bool any_bad = fps_bad || qp_bad || variance_bad;
+
+  if (!prev_any_bad && any_bad) {
+    LOG(LS_WARNING) << "Bad call (any) start: " << now;
+  } else if (prev_any_bad && !any_bad) {
+    LOG(LS_WARNING) << "Bad call (any) end: " << now;
+  }
+
+  if (!prev_fps_bad && fps_bad) {
+    LOG(LS_WARNING) << "Bad call (fps) start: " << now;
+  } else if (prev_fps_bad && !fps_bad) {
+    LOG(LS_WARNING) << "Bad call (fps) end: " << now;
+  }
+
+  if (!prev_qp_bad && qp_bad) {
+    LOG(LS_WARNING) << "Bad call (qp) start: " << now;
+  } else if (prev_qp_bad && !qp_bad) {
+    LOG(LS_WARNING) << "Bad call (qp) end: " << now;
+  }
+
+  if (!prev_variance_bad && variance_bad) {
+    LOG(LS_WARNING) << "Bad call (variance) start: " << now;
+  } else if (prev_variance_bad && !variance_bad) {
+    LOG(LS_WARNING) << "Bad call (variance) end: " << now;
+  }
+
+  LOG(LS_INFO) << "SAMPLE: sample_length: " << (now - last_sample_time_)
+               << " fps: " << fps << " fps_bad: " << fps_bad << " qp: " << qp
+               << " qp_bad: " << qp_bad << " variance_bad: " << variance_bad
+               << " fps_variance: " << fps_variance;
+
+  last_sample_time_ = now;
+  qp_sample_.Reset();
+}
+
 VideoReceiveStream::Stats ReceiveStatisticsProxy::GetStats() const {
   rtc::CritScope lock(&crit_);
   return stats_;
 }
 
 void ReceiveStatisticsProxy::OnIncomingPayloadType(int payload_type) {
   rtc::CritScope lock(&crit_);
   stats_.current_payload_type = payload_type;
 }
 
 void ReceiveStatisticsProxy::OnDecoderImplementationName(
     const char* implementation_name) {
   rtc::CritScope lock(&crit_);
   stats_.decoder_implementation_name = implementation_name;
 }
 void ReceiveStatisticsProxy::OnIncomingRate(unsigned int framerate,
                                             unsigned int bitrate_bps) {
   rtc::CritScope lock(&crit_);
+  QualitySample();
   stats_.network_frame_rate = framerate;
   stats_.total_bitrate_bps = bitrate_bps;
 }
 
 void ReceiveStatisticsProxy::OnDecoderTiming(int decode_ms,
                                              int max_decode_ms,
                                              int current_delay_ms,
                                              int target_delay_ms,
                                              int jitter_buffer_ms,
                                              int min_playout_delay_ms,
@@ skipping 126 matching lines @@
 }
 
 void ReceiveStatisticsProxy::OnPreDecode(
     const EncodedImage& encoded_image,
     const CodecSpecificInfo* codec_specific_info) {
   if (!codec_specific_info || encoded_image.qp_ == -1) {
     return;
   }
   if (codec_specific_info->codecType == kVideoCodecVP8) {
     qp_counters_.vp8.Add(encoded_image.qp_);
+    rtc::CritScope lock(&crit_);
+    qp_sample_.Add(encoded_image.qp_);
   }
 }
 
 void ReceiveStatisticsProxy::SampleCounter::Add(int sample) {
   sum += sample;
   ++num_samples;
 }
 
 int ReceiveStatisticsProxy::SampleCounter::Avg(int min_required_samples) const {
   if (num_samples < min_required_samples || num_samples == 0)
     return -1;
   return sum / num_samples;
 }
 
+void ReceiveStatisticsProxy::SampleCounter::Reset() {
+  num_samples = 0;
+  sum = 0;

[stefan-webrtc, 2016/11/28 15:55:25]

num_samples_
sum_

+}
+
 }  // namespace webrtc