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..29a617a8c70c71e2bc67a05aa954617648d8134f 100644
--- a/webrtc/video/overuse_frame_detector.cc
+++ b/webrtc/video/overuse_frame_detector.cc
@@ -20,7 +20,9 @@
 #include "webrtc/base/checks.h"
 #include "webrtc/base/exp_filter.h"
 #include "webrtc/base/logging.h"
+#include "webrtc/frame_callback.h"
 #include "webrtc/system_wrappers/include/clock.h"
+#include "webrtc/video_frame.h"
 
 namespace webrtc {
 
@@ -115,61 +117,15 @@ 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,
     CpuOveruseObserver* observer,
+    EncodedFrameObserver* encoder_timing,
     CpuOveruseMetricsObserver* metrics_observer)
     : options_(options),
       observer_(observer),
+      encoder_timing_(encoder_timing),
       metrics_observer_(metrics_observer),
       clock_(clock),
       num_process_times_(0),
@@ -183,33 +139,18 @@ 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();
   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_duration_ms) {
   metrics_.encode_usage_percent = usage_->Value();
 
-  metrics_observer_->CpuOveruseMetricsUpdated(metrics_);
+  metrics_observer_->OnEncodedFrameTimeMeasured(encode_duration_ms, metrics_);
 }
 
 int64_t OveruseFrameDetector::TimeUntilNextProcess() {
@@ -234,20 +175,18 @@ 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();
 }
 
-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 +194,45 @@ void OveruseFrameDetector::FrameCaptured(int width,
 
   last_capture_time_ = now;
 
-  frame_queue_->Start(capture_time_ms, now);
+  frame_timing_.push_back(
+      FrameTiming(frame.ntp_time_ms(), frame.timestamp(), now));
 }
 
-void OveruseFrameDetector::FrameSent(int64_t capture_time_ms) {
+void OveruseFrameDetector::FrameSent(uint32_t timestamp) {
   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 kEncodingTimeMeasureWindowMs = 1000;
+  int64_t now = clock_->TimeInMilliseconds();
+  for (auto& it : frame_timing_) {
+    if (it.timestamp == 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 < kEncodingTimeMeasureWindowMs)
+      break;
+    if (timing.last_send_ms != -1) {
+      int encode_duration_ms =
+          static_cast<int>(timing.last_send_ms - timing.capture_ms);
+      if (encoder_timing_) {
+        encoder_timing_->OnEncodeTiming(timing.capture_ntp_ms,
+                                        encode_duration_ms);
+      }
+      AddProcessingTime(encode_duration_ms);
+    }
+    frame_timing_.pop_front();
   }
 }
 
@@ -274,7 +243,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() {