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/field_trial.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 int kNumMeasurementsVariance = kNumMeasurements * 1.5;
+const float kBadFraction = 0.8f;
+// For fps and framerate variance:
+// Low means low enough to be bad, high means high enough to be good
+const int kLowFpsThreshold = 12;
+const int kHighFpsThreshold = 14;
+const int kLowVarianceThreshold = 1;

[åsapersson, 2016/12/07 15:34:51]

For variance, low enough to be good..?

+const int kHighVarianceThreshold = 2;
+// For qp:
+// Low means low enough to be good, high means high enough to be bad
+const int kLowQpThreshold = 60;
+const int kHighQpThreshold = 70;

[åsapersson, 2016/12/07 15:34:51]

Add Vp8 to variable name (since the qp range depends on the codec).

 }  // 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.

[åsapersson, 2016/12/07 15:34:50]

Move comment to decode_fps_estimator_

+      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),
       first_report_block_time_ms_(-1) {
   stats_.ssrc = config_.rtp.remote_ssrc;
   for (auto it : config_.rtp.rtx)
     rtx_stats_[it.second.ssrc] = StreamDataCounters();
 }
@@ skipping 122 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();
+

[åsapersson, 2016/12/07 15:34:50]

Perhaps check that some minimum time has passed since last_sample_time_.

+  double fps =
+      render_fps_tracker_.ComputeRateForInterval(now - last_sample_time_);
+  int qp = qp_sample_.Avg(1);

[åsapersson, 2016/12/07 15:34:51]

Handle -1 (i.e. no samples)?

[palmkvist, 2016/12/08 14:15:02]

My original thinking was that that was ok, since that either means lost frames
(i.e. fps will be bad, so we'll report bad anyway) or we're not getting qp data
at all (so qp cannot be a cause of a bad judgement), but I guess it's just as
well/better to just ignore it.

+
+  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 129 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;
+}
+
 }  // namespace webrtc