Measure encoding time on encode callbacks.

webrtc/video/overuse_frame_detector.cc

Index: webrtc/video/overuse_frame_detector.cc
diff --git a/webrtc/video/overuse_frame_detector.cc b/webrtc/video/overuse_frame_detector.cc
index d971ad9d3ef79427c2da93e0d8b5522ac7056344..493e44a4289c1886ddb105c39fddf0fe41d84314 100644
--- a/webrtc/video/overuse_frame_detector.cc
+++ b/webrtc/video/overuse_frame_detector.cc
@@ -21,6 +21,7 @@
 #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 {
 
@@ -115,54 +116,6 @@ class OveruseFrameDetector::SendProcessingUsage {
   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,
@@ -171,6 +124,7 @@ OveruseFrameDetector::OveruseFrameDetector(
     : options_(options),
       observer_(observer),
       metrics_observer_(metrics_observer),
+      last_encode_time_ms_(0),
       clock_(clock),
       num_process_times_(0),
       last_capture_time_(0),
@@ -183,33 +137,23 @@ OveruseFrameDetector::OveruseFrameDetector(
       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() {
@@ -234,20 +178,19 @@ bool OveruseFrameDetector::FrameTimeoutDetected(int64_t now) const {
 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)
@@ -255,15 +198,39 @@ void OveruseFrameDetector::FrameCaptured(int width,
 
   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();
   }
 }
 
@@ -274,7 +241,7 @@ void OveruseFrameDetector::AddProcessingTime(int elapsed_ms) {
     usage_->AddSample(elapsed_ms, diff_ms);
   }
   last_sample_time_ms_ = now;
-  UpdateCpuOveruseMetrics();
+  EncodedFrameTimeMeasured(elapsed_ms);
 }
 
 int32_t OveruseFrameDetector::Process() {