Move stats for delayed frames to renderer from VCMTiming to ReceiveStatisticsProxy.

Bug: none
Change-Id: If62cc40cf00bc4d657a31a89640d03812cff388e
Reviewed-on: https://webrtc-review.googlesource.com/74500
Commit-Queue: Åsa Persson <asapersson@webrtc.org>
Reviewed-by: Rasmus Brandt <brandtr@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#23526}

modules/video_coding/timing.cc

@@ -14,7 +14,6 @@
 
 #include "rtc_base/time/timestamp_extrapolator.h"
 #include "system_wrappers/include/clock.h"
-#include "system_wrappers/include/metrics.h"
 
 namespace webrtc {
 
@@ -31,10 +30,7 @@ VCMTiming::VCMTiming(Clock* clock, VCMTiming* master_timing)
       last_decode_ms_(0),
       prev_frame_timestamp_(0),
       timing_frame_info_(),
-      num_decoded_frames_(0),
+      num_decoded_frames_(0) {
-      num_delayed_decoded_frames_(0),
-      first_decoded_frame_ms_(-1),
-      sum_missed_render_deadline_ms_(0) {
   if (master_timing == NULL) {
     master_ = true;
     ts_extrapolator_ = new TimestampExtrapolator(clock_->TimeInMilliseconds());
@@ -44,33 +40,11 @@ VCMTiming::VCMTiming(Clock* clock, VCMTiming* master_timing)
 }
 
 VCMTiming::~VCMTiming() {
-  UpdateHistograms();
   if (master_) {
     delete ts_extrapolator_;
   }
 }
 
-// TODO(asapersson): Move stats to ReceiveStatisticsProxy.
-void VCMTiming::UpdateHistograms() const {
-  rtc::CritScope cs(&crit_sect_);
-  if (num_decoded_frames_ == 0) {
-    return;
-  }
-  int64_t elapsed_sec =
-      (clock_->TimeInMilliseconds() - first_decoded_frame_ms_) / 1000;
-  if (elapsed_sec < metrics::kMinRunTimeInSeconds) {
-    return;
-  }
-  RTC_HISTOGRAM_PERCENTAGE(
-      "WebRTC.Video.DelayedFramesToRenderer",
-      num_delayed_decoded_frames_ * 100 / num_decoded_frames_);
-  if (num_delayed_decoded_frames_ > 0) {
-    RTC_HISTOGRAM_COUNTS_1000(
-        "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs",
-        sum_missed_render_deadline_ms_ / num_delayed_decoded_frames_);
-  }
-}
-
 void VCMTiming::Reset() {
   rtc::CritScope cs(&crit_sect_);
   ts_extrapolator_->Reset(clock_->TimeInMilliseconds());
@@ -183,17 +157,7 @@ void VCMTiming::StopDecodeTimer(uint32_t time_stamp,
   codec_timer_->AddTiming(decode_time_ms, now_ms);
   assert(decode_time_ms >= 0);
   last_decode_ms_ = decode_time_ms;
-
-  // Update stats.
   ++num_decoded_frames_;
-  if (num_decoded_frames_ == 1) {
-    first_decoded_frame_ms_ = now_ms;
-  }
-  int time_until_rendering_ms = render_time_ms - render_delay_ms_ - now_ms;
-  if (time_until_rendering_ms < 0) {
-    sum_missed_render_deadline_ms_ += -time_until_rendering_ms;
-    ++num_delayed_decoded_frames_;
-  }
 }
 
 void VCMTiming::IncomingTimestamp(uint32_t time_stamp, int64_t now_ms) {

modules/video_coding/timing.h

@@ -107,8 +107,6 @@ class VCMTiming {
   int TargetDelayInternal() const RTC_EXCLUSIVE_LOCKS_REQUIRED(crit_sect_);
 
  private:
-  void UpdateHistograms() const;
-
   rtc::CriticalSection crit_sect_;
   Clock* const clock_;
   bool master_ RTC_GUARDED_BY(crit_sect_);
@@ -127,12 +125,7 @@ class VCMTiming {
   int last_decode_ms_ RTC_GUARDED_BY(crit_sect_);
   uint32_t prev_frame_timestamp_ RTC_GUARDED_BY(crit_sect_);
   rtc::Optional<TimingFrameInfo> timing_frame_info_ RTC_GUARDED_BY(crit_sect_);
-
-  // Statistics.
   size_t num_decoded_frames_ RTC_GUARDED_BY(crit_sect_);
-  size_t num_delayed_decoded_frames_ RTC_GUARDED_BY(crit_sect_);
-  int64_t first_decoded_frame_ms_ RTC_GUARDED_BY(crit_sect_);
-  uint64_t sum_missed_render_deadline_ms_ RTC_GUARDED_BY(crit_sect_);
 };
 }  // namespace webrtc
 

video/end_to_end_tests/histogram_tests.cc

@@ -60,10 +60,9 @@ void HistogramTest::VerifyHistogramStats(bool use_rtx,
 
     bool MinMetricRunTimePassed() {
       int64_t now_ms = Clock::GetRealTimeClock()->TimeInMilliseconds();
-      if (!start_runtime_ms_) {
+      if (!start_runtime_ms_)
         start_runtime_ms_ = now_ms;
-        return false;
+
-      }
       int64_t elapsed_sec = (now_ms - *start_runtime_ms_) / 1000;
       return elapsed_sec > metrics::kMinRunTimeInSeconds * 2;
     }
@@ -192,6 +191,7 @@ void HistogramTest::VerifyHistogramStats(bool use_rtx,
   EXPECT_EQ(1, metrics::NumSamples(video_prefix + "SentFramesPerSecond"));
   EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.DecodedFramesPerSecond"));
   EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.RenderFramesPerSecond"));
+  EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
 
   EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.JitterBufferDelayInMs"));
   EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.TargetDelayInMs"));

video/receive_statistics_proxy.cc

@@ -114,6 +114,8 @@ ReceiveStatisticsProxy::ReceiveStatisticsProxy(
       avg_rtt_ms_(0),
       last_content_type_(VideoContentType::UNSPECIFIED),
       last_codec_type_(kVideoCodecVP8),
+      num_delayed_frames_rendered_(0),
+      sum_missed_render_deadline_ms_(0),
       timing_frame_info_counter_(kMovingMaxWindowMs) {
   decode_thread_.DetachFromThread();
   network_thread_.DetachFromThread();
@@ -181,6 +183,19 @@ void ReceiveStatisticsProxy::UpdateHistograms() {
           "WebRTC.Video.DecodedFramesPerSecond",
           static_cast<int>((stats_.frames_decoded * 1000.0f / elapsed_ms) +
                            0.5f));
+
+      const uint32_t frames_rendered = stats_.frames_rendered;
+      if (frames_rendered > 0) {
+        RTC_HISTOGRAM_PERCENTAGE("WebRTC.Video.DelayedFramesToRenderer",
+                                 static_cast<int>(num_delayed_frames_rendered_ *
+                                                  100 / frames_rendered));
+        if (num_delayed_frames_rendered_ > 0) {
+          RTC_HISTOGRAM_COUNTS_1000(
+              "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs",
+              static_cast<int>(sum_missed_render_deadline_ms_ /
+                               num_delayed_frames_rendered_));
+        }
+      }
     }
   }
 
@@ -742,11 +757,11 @@ void ReceiveStatisticsProxy::OnRenderedFrame(const VideoFrame& frame) {
   int height = frame.height();
   RTC_DCHECK_GT(width, 0);
   RTC_DCHECK_GT(height, 0);
-  uint64_t now = clock_->TimeInMilliseconds();
+  int64_t now_ms = clock_->TimeInMilliseconds();
   rtc::CritScope lock(&crit_);
   ContentSpecificStats* content_specific_stats =
       &content_specific_stats_[last_content_type_];
-  renders_fps_estimator_.Update(1, now);
+  renders_fps_estimator_.Update(1, now_ms);
   ++stats_.frames_rendered;
   stats_.width = width;
   stats_.height = height;
@@ -755,6 +770,13 @@ void ReceiveStatisticsProxy::OnRenderedFrame(const VideoFrame& frame) {
   content_specific_stats->received_width.Add(width);
   content_specific_stats->received_height.Add(height);
 
+  // Consider taking stats_.render_delay_ms into account.
+  const int64_t time_until_rendering_ms = frame.render_time_ms() - now_ms;
+  if (time_until_rendering_ms < 0) {
+    sum_missed_render_deadline_ms_ += -time_until_rendering_ms;
+    ++num_delayed_frames_rendered_;
+  }
+
   if (frame.ntp_time_ms() > 0) {
     int64_t delay_ms = clock_->CurrentNtpInMilliseconds() - frame.ntp_time_ms();
     if (delay_ms >= 0) {

video/receive_statistics_proxy.h

@@ -185,6 +185,8 @@ class ReceiveStatisticsProxy : public VCMReceiveStatisticsCallback,
   VideoCodecType last_codec_type_ RTC_GUARDED_BY(&crit_);
   rtc::Optional<int64_t> first_decoded_frame_time_ms_ RTC_GUARDED_BY(&crit_);
   rtc::Optional<int64_t> last_decoded_frame_time_ms_ RTC_GUARDED_BY(&crit_);
+  size_t num_delayed_frames_rendered_ RTC_GUARDED_BY(&crit_);
+  int64_t sum_missed_render_deadline_ms_ RTC_GUARDED_BY(&crit_);
   // Mutable because calling Max() on MovingMaxCounter is not const. Yet it is
   // called from const GetStats().
   mutable rtc::MovingMaxCounter<TimingFrameInfo> timing_frame_info_counter_

video/receive_statistics_proxy_unittest.cc

@@ -28,7 +28,6 @@ const int64_t kFreqOffsetProcessIntervalInMs = 40000;
 const uint32_t kLocalSsrc = 123;
 const uint32_t kRemoteSsrc = 456;
 const int kMinRequiredSamples = 200;
-
 const int kWidth = 1280;
 const int kHeight = 720;
 
@@ -61,7 +60,16 @@ class ReceiveStatisticsProxyTest
   }
 
   VideoFrame CreateFrame(int width, int height) {
-    VideoFrame frame(I420Buffer::Create(width, height), 0, 0, kVideoRotation_0);
+    return CreateVideoFrame(width, height, 0);
+  }
+
+  VideoFrame CreateFrameWithRenderTimeMs(int64_t render_time_ms) {
+    return CreateVideoFrame(kWidth, kHeight, render_time_ms);
+  }
+
+  VideoFrame CreateVideoFrame(int width, int height, int64_t render_time_ms) {
+    VideoFrame frame(I420Buffer::Create(width, height), 0, render_time_ms,
+                     kVideoRotation_0);
     frame.set_ntp_time_ms(fake_clock_.CurrentNtpInMilliseconds());
     return frame;
   }
@@ -725,9 +733,6 @@ TEST_F(ReceiveStatisticsProxyTest, TimingHistogramsAreUpdated) {
 
 TEST_F(ReceiveStatisticsProxyTest, DoesNotReportStaleFramerates) {
   const int kDefaultFps = 30;
-  const int kWidth = 320;
-  const int kHeight = 240;
-
   rtc::scoped_refptr<VideoFrameBuffer> video_frame_buffer(
       I420Buffer::Create(kWidth, kHeight));
   VideoFrame frame(video_frame_buffer, kVideoRotation_0, 0);
@@ -752,8 +757,6 @@ TEST_F(ReceiveStatisticsProxyTest, DoesNotReportStaleFramerates) {
 }
 
 TEST_F(ReceiveStatisticsProxyTest, GetStatsReportsReceivedFrameStats) {
-  const int kWidth = 160;
-  const int kHeight = 120;
   EXPECT_EQ(0, statistics_proxy_->GetStats().width);
   EXPECT_EQ(0, statistics_proxy_->GetStats().height);
   EXPECT_EQ(0u, statistics_proxy_->GetStats().frames_rendered);
@@ -767,9 +770,6 @@ TEST_F(ReceiveStatisticsProxyTest, GetStatsReportsReceivedFrameStats) {
 
 TEST_F(ReceiveStatisticsProxyTest,
        ReceivedFrameHistogramsAreNotUpdatedForTooFewSamples) {
-  const int kWidth = 160;
-  const int kHeight = 120;
-
   for (int i = 0; i < kMinRequiredSamples - 1; ++i)
     statistics_proxy_->OnRenderedFrame(CreateFrame(kWidth, kHeight));
 
@@ -781,9 +781,6 @@ TEST_F(ReceiveStatisticsProxyTest,
 }
 
 TEST_F(ReceiveStatisticsProxyTest, ReceivedFrameHistogramsAreUpdated) {
-  const int kWidth = 160;
-  const int kHeight = 120;
-
   for (int i = 0; i < kMinRequiredSamples; ++i)
     statistics_proxy_->OnRenderedFrame(CreateFrame(kWidth, kHeight));
 
@@ -798,6 +795,95 @@ TEST_F(ReceiveStatisticsProxyTest, ReceivedFrameHistogramsAreUpdated) {
             metrics::NumEvents("WebRTC.Video.ReceivedHeightInPixels", kHeight));
 }
 
+TEST_F(ReceiveStatisticsProxyTest, ZeroDelayReportedIfFrameNotDelayed) {
+  statistics_proxy_->OnDecodedFrame(rtc::nullopt, kWidth, kHeight,
+                                    VideoContentType::UNSPECIFIED);
+
+  // Frame not delayed, delayed frames to render: 0%.
+  const int64_t kNowMs = fake_clock_.TimeInMilliseconds();
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs));
+
+  // Min run time has passed.
+  fake_clock_.AdvanceTimeMilliseconds((metrics::kMinRunTimeInSeconds * 1000));
+  statistics_proxy_.reset();
+  EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
+  EXPECT_EQ(1, metrics::NumEvents("WebRTC.Video.DelayedFramesToRenderer", 0));
+  EXPECT_EQ(0, metrics::NumSamples(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs"));
+}
+
+TEST_F(ReceiveStatisticsProxyTest,
+       DelayedFrameHistogramsAreNotUpdatedIfMinRuntimeHasNotPassed) {
+  statistics_proxy_->OnDecodedFrame(rtc::nullopt, kWidth, kHeight,
+                                    VideoContentType::UNSPECIFIED);
+
+  // Frame not delayed, delayed frames to render: 0%.
+  const int64_t kNowMs = fake_clock_.TimeInMilliseconds();
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs));
+
+  // Min run time has not passed.
+  fake_clock_.AdvanceTimeMilliseconds((metrics::kMinRunTimeInSeconds * 1000) -
+                                      1);
+  statistics_proxy_.reset();
+  EXPECT_EQ(0, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
+  EXPECT_EQ(0, metrics::NumSamples(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs"));
+}
+
+TEST_F(ReceiveStatisticsProxyTest,
+       DelayedFramesHistogramsAreNotUpdatedIfNoRenderedFrames) {
+  statistics_proxy_->OnDecodedFrame(rtc::nullopt, kWidth, kHeight,
+                                    VideoContentType::UNSPECIFIED);
+
+  // Min run time has passed. No rendered frames.
+  fake_clock_.AdvanceTimeMilliseconds((metrics::kMinRunTimeInSeconds * 1000));
+  statistics_proxy_.reset();
+  EXPECT_EQ(0, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
+  EXPECT_EQ(0, metrics::NumSamples(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs"));
+}
+
+TEST_F(ReceiveStatisticsProxyTest, DelayReportedIfFrameIsDelayed) {
+  statistics_proxy_->OnDecodedFrame(rtc::nullopt, kWidth, kHeight,
+                                    VideoContentType::UNSPECIFIED);
+
+  // Frame delayed 1 ms, delayed frames to render: 100%.
+  const int64_t kNowMs = fake_clock_.TimeInMilliseconds();
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs - 1));
+
+  // Min run time has passed.
+  fake_clock_.AdvanceTimeMilliseconds((metrics::kMinRunTimeInSeconds * 1000));
+  statistics_proxy_.reset();
+  EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
+  EXPECT_EQ(1, metrics::NumEvents("WebRTC.Video.DelayedFramesToRenderer", 100));
+  EXPECT_EQ(1, metrics::NumSamples(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs"));
+  EXPECT_EQ(1, metrics::NumEvents(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs", 1));
+}
+
+TEST_F(ReceiveStatisticsProxyTest, AverageDelayOfDelayedFramesIsReported) {
+  statistics_proxy_->OnDecodedFrame(rtc::nullopt, kWidth, kHeight,
+                                    VideoContentType::UNSPECIFIED);
+
+  // Two frames delayed (6 ms, 10 ms), delayed frames to render: 50%.
+  const int64_t kNowMs = fake_clock_.TimeInMilliseconds();
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs - 10));
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs - 6));
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs));
+  statistics_proxy_->OnRenderedFrame(CreateFrameWithRenderTimeMs(kNowMs + 1));
+
+  // Min run time has passed.
+  fake_clock_.AdvanceTimeMilliseconds((metrics::kMinRunTimeInSeconds * 1000));
+  statistics_proxy_.reset();
+  EXPECT_EQ(1, metrics::NumSamples("WebRTC.Video.DelayedFramesToRenderer"));
+  EXPECT_EQ(1, metrics::NumEvents("WebRTC.Video.DelayedFramesToRenderer", 50));
+  EXPECT_EQ(1, metrics::NumSamples(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs"));
+  EXPECT_EQ(1, metrics::NumEvents(
+                   "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs", 8));
+}
+
 TEST_F(ReceiveStatisticsProxyTest,
        RtcpHistogramsNotUpdatedIfMinRuntimeHasNotPassed) {
   InsertFirstRtpPacket(kRemoteSsrc);