Measure encoding time on encode callbacks.

webrtc/video/overuse_frame_detector.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/overuse_frame_detector.h"
 
 #include <assert.h>
 #include <math.h>
 
 #include <algorithm>
 #include <list>
 #include <map>
 
 #include "webrtc/base/checks.h"
 #include "webrtc/base/exp_filter.h"
 #include "webrtc/base/logging.h"
 #include "webrtc/system_wrappers/include/clock.h"
+#include "webrtc/video_frame.h"
 
 namespace webrtc {
 
 namespace {
 const int64_t kProcessIntervalMs = 5000;
 
 // Delay between consecutive rampups. (Used for quick recovery.)
 const int kQuickRampUpDelayMs = 10 * 1000;
 // Delay between rampup attempts. Initially uses standard, scales up to max.
 const int kStandardRampUpDelayMs = 40 * 1000;
@@ skipping 74 matching lines @@
   const float kWeightFactorFrameDiff;
   const float kWeightFactorProcessing;
   const float kInitialSampleDiffMs;
   const float kMaxSampleDiffMs;
   uint64_t count_;
   const CpuOveruseOptions options_;
   rtc::scoped_ptr<rtc::ExpFilter> filtered_processing_ms_;
   rtc::scoped_ptr<rtc::ExpFilter> filtered_frame_diff_ms_;
 };
 
-// Class for calculating the processing time of frames.
-class OveruseFrameDetector::FrameQueue {
- public:
-  FrameQueue() : last_processing_time_ms_(-1) {}
-  ~FrameQueue() {}
-
-  // Called when a frame is captured.
-  // Starts the measuring of the processing time of the frame.
-  void Start(int64_t capture_time, int64_t now) {
-    const size_t kMaxSize = 90;  // Allows for processing time of 1.5s at 60fps.
-    if (frame_times_.size() > kMaxSize) {
-      LOG(LS_WARNING) << "Max size reached, removed oldest frame.";
-      frame_times_.erase(frame_times_.begin());
-    }
-    if (frame_times_.find(capture_time) != frame_times_.end()) {
-      // Frame should not exist.
-      assert(false);
-      return;
-    }
-    frame_times_[capture_time] = now;
-  }
-
-  // Called when the processing of a frame has finished.
-  // Returns the processing time of the frame.
-  int End(int64_t capture_time, int64_t now) {
-    std::map<int64_t, int64_t>::iterator it = frame_times_.find(capture_time);
-    if (it == frame_times_.end()) {
-      return -1;
-    }
-    // Remove any old frames up to current.
-    // Old frames have been skipped by the capture process thread.
-    // TODO(asapersson): Consider measuring time from first frame in list.
-    last_processing_time_ms_ = now - (*it).second;
-    frame_times_.erase(frame_times_.begin(), ++it);
-    return last_processing_time_ms_;
-  }
-
-  void Reset() { frame_times_.clear(); }
-  int NumFrames() const { return static_cast<int>(frame_times_.size()); }
-  int last_processing_time_ms() const { return last_processing_time_ms_; }
-
- private:
-  // Captured frames mapped by the capture time.
-  std::map<int64_t, int64_t> frame_times_;
-  int last_processing_time_ms_;
-};
-
-
 OveruseFrameDetector::OveruseFrameDetector(
     Clock* clock,
     const CpuOveruseOptions& options,
     CpuOveruseObserver* observer,
     CpuOveruseMetricsObserver* metrics_observer)
     : options_(options),
       observer_(observer),
       metrics_observer_(metrics_observer),
+      last_encode_time_ms_(0),
       clock_(clock),
       num_process_times_(0),
       last_capture_time_(0),
       num_pixels_(0),
       next_process_time_(clock_->TimeInMilliseconds()),
       last_overuse_time_(0),
       checks_above_threshold_(0),
       num_overuse_detections_(0),
       last_rampup_time_(0),
       in_quick_rampup_(false),
       current_rampup_delay_ms_(kStandardRampUpDelayMs),
       last_sample_time_ms_(0),
-      usage_(new SendProcessingUsage(options)),
-      frame_queue_(new FrameQueue()) {
+      usage_(new SendProcessingUsage(options)) {
   RTC_DCHECK(metrics_observer != nullptr);
   // Make sure stats are initially up-to-date. This simplifies unit testing
   // since we don't have to trigger an update using one of the methods which
   // would also alter the overuse state.
-  UpdateCpuOveruseMetrics();
+  EncodedFrameTimeMeasured(0);

[mflodman, 2016/01/21 08:00:04]

Is this really needed? For the callback or to actually set values?

1. If it is to set the values, it would be better to set them as default right
away instead.

2. If it is for the callback, we can just call the callback instead.

Or both 1 and 2.

[pbos-webrtc, 2016/01/21 14:18:33]

Removed, I don't think we should have to report the current values before we've
measured them.

   processing_thread_.DetachFromThread();
 }
 
 OveruseFrameDetector::~OveruseFrameDetector() {
 }
 
-int OveruseFrameDetector::LastProcessingTimeMs() const {
-  rtc::CritScope cs(&crit_);
-  return frame_queue_->last_processing_time_ms();
-}
-
-int OveruseFrameDetector::FramesInQueue() const {
-  rtc::CritScope cs(&crit_);
-  return frame_queue_->NumFrames();
-}
-
-void OveruseFrameDetector::UpdateCpuOveruseMetrics() {
+void OveruseFrameDetector::EncodedFrameTimeMeasured(int encode_time_ms) {

[mflodman, 2016/01/21 08:00:04]

I'd prefer encoded_time_ms or encoder_process_time or something telling this is
the time it took to encode a frame rather than a wall clock time.

[pbos-webrtc, 2016/01/21 14:18:33]

encode_duration_ms done

+  last_encode_time_ms_ = encode_time_ms;
   metrics_.encode_usage_percent = usage_->Value();
 
-  metrics_observer_->CpuOveruseMetricsUpdated(metrics_);
+  metrics_observer_->OnEncodedFrameTimeMeasured(encode_time_ms, metrics_);
 }
 
 int64_t OveruseFrameDetector::TimeUntilNextProcess() {
   RTC_DCHECK(processing_thread_.CalledOnValidThread());
   return next_process_time_ - clock_->TimeInMilliseconds();
 }
 
 bool OveruseFrameDetector::FrameSizeChanged(int num_pixels) const {
   if (num_pixels != num_pixels_) {
     return true;
   }
   return false;
 }
 
 bool OveruseFrameDetector::FrameTimeoutDetected(int64_t now) const {
   if (last_capture_time_ == 0) {
     return false;
   }
   return (now - last_capture_time_) > options_.frame_timeout_interval_ms;
 }
 
 void OveruseFrameDetector::ResetAll(int num_pixels) {
   num_pixels_ = num_pixels;
   usage_->Reset();
-  frame_queue_->Reset();
+  frame_timing_.clear();
   last_capture_time_ = 0;
   num_process_times_ = 0;
-  UpdateCpuOveruseMetrics();
+  EncodedFrameTimeMeasured(last_encode_time_ms_);

[mflodman, 2016/01/21 08:00:05]

Do we need this here? What is the benefit compared to just calling with 0 as
done initially? (i.e. is it worth having this member for this?)

[pbos-webrtc, 2016/01/21 14:18:33]

No don't think we need to re-report here even.

 }
 
-void OveruseFrameDetector::FrameCaptured(int width,
-                                         int height,
-                                         int64_t capture_time_ms) {
+void OveruseFrameDetector::FrameCaptured(const VideoFrame& frame) {
   rtc::CritScope cs(&crit_);
 
   int64_t now = clock_->TimeInMilliseconds();
-  if (FrameSizeChanged(width * height) || FrameTimeoutDetected(now)) {
-    ResetAll(width * height);
+  if (FrameSizeChanged(frame.width() * frame.height()) ||
+      FrameTimeoutDetected(now)) {
+    ResetAll(frame.width() * frame.height());
   }
 
   if (last_capture_time_ != 0)
     usage_->AddCaptureSample(now - last_capture_time_);
 
   last_capture_time_ = now;
 
-  frame_queue_->Start(capture_time_ms, now);
+  frame_timing_.push_back(FrameTiming(frame.timestamp(), now));

[mflodman, 2016/01/21 08:00:04]

Is it better to use timestamp than capture_time_ms_?

[pbos-webrtc, 2016/01/21 14:18:33]

We don't get capture_time_ms out of the encoder after encoding. If we're lucky
we get correct RTP timestamps (true except for ChromeOS).

[mflodman, 2016/02/05 08:19:03]

Maybe this is something we should do in the future.

 }
 
-void OveruseFrameDetector::FrameSent(int64_t capture_time_ms) {
+void OveruseFrameDetector::FrameSent(const EncodedImage& frame) {
   rtc::CritScope cs(&crit_);
-  int delay_ms = frame_queue_->End(capture_time_ms,
-                                   clock_->TimeInMilliseconds());
-  if (delay_ms > 0) {
-    AddProcessingTime(delay_ms);
+  // Delay before reporting actual encoding time, used to have the ability to
+  // detect total encoding time when encoding more than one layer. Encoding is
+  // here assumed to finish within a second (or that we get enough long-time
+  // samples before one second to trigger an overuse even when this is not the
+  // case).
+  static const int64_t kEncodingTimeDelayMs = 1000;

[mflodman, 2016/01/21 08:00:04]

I'd prefer to call this something indicating this is the max delay used to
measure, now this can be confused with the actual encoding time. I'll give this
some more thoughts.

[pbos-webrtc, 2016/01/21 14:18:33]

kEncodingTimeMeasureWindowsMs, let me know if you have something
shorter/snappier.

+  int64_t now = clock_->TimeInMilliseconds();
+  for (auto& it : frame_timing_) {
+    if (it.timestamp == frame._timeStamp) {
+      it.last_send_ms = now;
+      break;
+    }
+  }
+  // TODO(pbos): Handle the case/log errors when not finding the corresponding
+  // frame (either very slow encoding or incorrect wrong timestamps returned
+  // from the encoder).
+  // This is currently the case for all frames on ChromeOS, so logging them
+  // would be spammy, and triggering overuse would be wrong.
+  // https://crbug.com/350106
+  while (!frame_timing_.empty()) {
+    FrameTiming timing = frame_timing_.front();
+    if (now - timing.capture_ms < kEncodingTimeDelayMs)
+      break;
+    if (timing.last_send_ms != -1) {
+      AddProcessingTime(
+          static_cast<int>(timing.last_send_ms - timing.capture_ms));
+    }
+    frame_timing_.pop_front();
   }
 }
 
 void OveruseFrameDetector::AddProcessingTime(int elapsed_ms) {
   int64_t now = clock_->TimeInMilliseconds();
   if (last_sample_time_ms_ != 0) {
     int64_t diff_ms = now - last_sample_time_ms_;
     usage_->AddSample(elapsed_ms, diff_ms);
   }
   last_sample_time_ms_ = now;
-  UpdateCpuOveruseMetrics();
+  EncodedFrameTimeMeasured(elapsed_ms);
 }
 
 int32_t OveruseFrameDetector::Process() {
   RTC_DCHECK(processing_thread_.CalledOnValidThread());
 
   int64_t now = clock_->TimeInMilliseconds();
 
   // Used to protect against Process() being called too often.
   if (now < next_process_time_)
     return 0;
@@ skipping 67 matching lines @@
 bool OveruseFrameDetector::IsUnderusing(const CpuOveruseMetrics& metrics,
                                         int64_t time_now) {
   int delay = in_quick_rampup_ ? kQuickRampUpDelayMs : current_rampup_delay_ms_;
   if (time_now < last_rampup_time_ + delay)
     return false;
 
   return metrics.encode_usage_percent <
          options_.low_encode_usage_threshold_percent;
 }
 }  // namespace webrtc