From 81327d54f3ad47e2a1722c5849ea52884c221658 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C3=85sa=20Persson?= Date: Tue, 5 Jun 2018 13:34:33 +0200 Subject: [PATCH] Move stats for delayed frames to renderer from VCMTiming to ReceiveStatisticsProxy. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bug: none Change-Id: If62cc40cf00bc4d657a31a89640d03812cff388e Reviewed-on: https://webrtc-review.googlesource.com/74500 Commit-Queue: Åsa Persson Reviewed-by: Rasmus Brandt Cr-Commit-Position: refs/heads/master@{#23526} --- modules/video_coding/timing.cc | 38 +------ modules/video_coding/timing.h | 7 -- video/end_to_end_tests/histogram_tests.cc | 6 +- video/receive_statistics_proxy.cc | 26 ++++- video/receive_statistics_proxy.h | 2 + video/receive_statistics_proxy_unittest.cc | 112 ++++++++++++++++++--- 6 files changed, 129 insertions(+), 62 deletions(-) diff --git a/modules/video_coding/timing.cc b/modules/video_coding/timing.cc index cf600199a4..40b8340e30 100644 --- a/modules/video_coding/timing.cc +++ b/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_delayed_decoded_frames_(0), - first_decoded_frame_ms_(-1), - sum_missed_render_deadline_ms_(0) { + num_decoded_frames_(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) { diff --git a/modules/video_coding/timing.h b/modules/video_coding/timing.h index 71c6f33cec..8c04ce2c40 100644 --- a/modules/video_coding/timing.h +++ b/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 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 diff --git a/video/end_to_end_tests/histogram_tests.cc b/video/end_to_end_tests/histogram_tests.cc index 67a01c941e..c3a86b47f9 100644 --- a/video/end_to_end_tests/histogram_tests.cc +++ b/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")); diff --git a/video/receive_statistics_proxy.cc b/video/receive_statistics_proxy.cc index 0f92f6aca7..0fe366aa77 100644 --- a/video/receive_statistics_proxy.cc +++ b/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((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(num_delayed_frames_rendered_ * + 100 / frames_rendered)); + if (num_delayed_frames_rendered_ > 0) { + RTC_HISTOGRAM_COUNTS_1000( + "WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs", + static_cast(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) { diff --git a/video/receive_statistics_proxy.h b/video/receive_statistics_proxy.h index 7d399be45e..1ec0039904 100644 --- a/video/receive_statistics_proxy.h +++ b/video/receive_statistics_proxy.h @@ -185,6 +185,8 @@ class ReceiveStatisticsProxy : public VCMReceiveStatisticsCallback, VideoCodecType last_codec_type_ RTC_GUARDED_BY(&crit_); rtc::Optional first_decoded_frame_time_ms_ RTC_GUARDED_BY(&crit_); rtc::Optional 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 timing_frame_info_counter_ diff --git a/video/receive_statistics_proxy_unittest.cc b/video/receive_statistics_proxy_unittest.cc index c3bc458848..149c8098f8 100644 --- a/video/receive_statistics_proxy_unittest.cc +++ b/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 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);