From f24476082724623ce27832ecb990ea9b415e6fca Mon Sep 17 00:00:00 2001 From: "asapersson@webrtc.org" Date: Tue, 9 Dec 2014 14:13:26 +0000 Subject: [PATCH] Add histograms for receive statistics: - decoded frames per second ("WebRTC.Video.DecodedFramesPerSecond") - percentage of delayed frames to rendered ("WebRTC.Video.DelayedFramesToRenderer") - average delay (of delayed frames) to renderer ("WebRTC.Video.DelayedFramesToRenderer_AvgDelayInMs") BUG=crbug/419657 R=stefan@webrtc.org Review URL: https://webrtc-codereview.appspot.com/26319004 git-svn-id: http://webrtc.googlecode.com/svn/trunk@7847 4adac7df-926f-26a2-2b94-8c16560cd09d --- .../main/source/generic_decoder.cc | 3 +- .../video_coding/main/source/timing.cc | 43 ++++++++++++++++++- .../modules/video_coding/main/source/timing.h | 11 ++++- .../main/source/timing_unittest.cc | 3 +- 4 files changed, 55 insertions(+), 5 deletions(-) diff --git a/webrtc/modules/video_coding/main/source/generic_decoder.cc b/webrtc/modules/video_coding/main/source/generic_decoder.cc index cb0faf9a9..4f8a7ca7d 100644 --- a/webrtc/modules/video_coding/main/source/generic_decoder.cc +++ b/webrtc/modules/video_coding/main/source/generic_decoder.cc @@ -68,7 +68,8 @@ int32_t VCMDecodedFrameCallback::Decoded(I420VideoFrame& decodedImage) _timing.StopDecodeTimer( decodedImage.timestamp(), frameInfo->decodeStartTimeMs, - _clock->TimeInMilliseconds()); + _clock->TimeInMilliseconds(), + frameInfo->renderTimeMs); if (callback != NULL) { diff --git a/webrtc/modules/video_coding/main/source/timing.cc b/webrtc/modules/video_coding/main/source/timing.cc index 2ec149ce8..0e2fddf08 100644 --- a/webrtc/modules/video_coding/main/source/timing.cc +++ b/webrtc/modules/video_coding/main/source/timing.cc @@ -13,6 +13,7 @@ #include "webrtc/modules/video_coding/main/source/internal_defines.h" #include "webrtc/modules/video_coding/main/source/jitter_buffer_common.h" #include "webrtc/system_wrappers/interface/clock.h" +#include "webrtc/system_wrappers/interface/metrics.h" #include "webrtc/system_wrappers/interface/timestamp_extrapolator.h" @@ -30,7 +31,11 @@ VCMTiming::VCMTiming(Clock* clock, jitter_delay_ms_(0), current_delay_ms_(0), last_decode_ms_(0), - prev_frame_timestamp_(0) { + prev_frame_timestamp_(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()); @@ -40,12 +45,34 @@ VCMTiming::VCMTiming(Clock* clock, } VCMTiming::~VCMTiming() { + UpdateHistograms(); if (master_) { delete ts_extrapolator_; } delete crit_sect_; } +void VCMTiming::UpdateHistograms() const { + CriticalSectionScoped 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_COUNTS_100("WebRTC.Video.DecodedFramesPerSecond", + static_cast((num_decoded_frames_ / elapsed_sec) + 0.5f)); + 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() { CriticalSectionScoped cs(crit_sect_); ts_extrapolator_->Reset(clock_->TimeInMilliseconds()); @@ -139,11 +166,23 @@ void VCMTiming::UpdateCurrentDelay(int64_t render_time_ms, int32_t VCMTiming::StopDecodeTimer(uint32_t time_stamp, int64_t start_time_ms, - int64_t now_ms) { + int64_t now_ms, + int64_t render_time_ms) { CriticalSectionScoped cs(crit_sect_); int32_t time_diff_ms = codec_timer_.StopTimer(start_time_ms, now_ms); assert(time_diff_ms >= 0); last_decode_ms_ = time_diff_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_; + } return 0; } diff --git a/webrtc/modules/video_coding/main/source/timing.h b/webrtc/modules/video_coding/main/source/timing.h index bb44a93b6..61c027301 100644 --- a/webrtc/modules/video_coding/main/source/timing.h +++ b/webrtc/modules/video_coding/main/source/timing.h @@ -59,7 +59,8 @@ class VCMTiming { // or when the decoded frame callback is called. int32_t StopDecodeTimer(uint32_t time_stamp, int64_t start_time_ms, - int64_t now_ms); + int64_t now_ms, + int64_t render_time_ms); // Used to report that a frame is passed to decoding. Updates the timestamp // filter which is used to map between timestamps and receiver system time. @@ -101,6 +102,8 @@ class VCMTiming { uint32_t TargetDelayInternal() const EXCLUSIVE_LOCKS_REQUIRED(crit_sect_); private: + void UpdateHistograms() const; + CriticalSectionWrapper* crit_sect_; Clock* const clock_; bool master_ GUARDED_BY(crit_sect_); @@ -112,6 +115,12 @@ class VCMTiming { uint32_t current_delay_ms_ GUARDED_BY(crit_sect_); int last_decode_ms_ GUARDED_BY(crit_sect_); uint32_t prev_frame_timestamp_ GUARDED_BY(crit_sect_); + + // Statistics. + size_t num_decoded_frames_ GUARDED_BY(crit_sect_); + size_t num_delayed_decoded_frames_ GUARDED_BY(crit_sect_); + int64_t first_decoded_frame_ms_ GUARDED_BY(crit_sect_); + uint64_t sum_missed_render_deadline_ms_ GUARDED_BY(crit_sect_); }; } // namespace webrtc diff --git a/webrtc/modules/video_coding/main/source/timing_unittest.cc b/webrtc/modules/video_coding/main/source/timing_unittest.cc index dde26a9c9..32df31c63 100644 --- a/webrtc/modules/video_coding/main/source/timing_unittest.cc +++ b/webrtc/modules/video_coding/main/source/timing_unittest.cc @@ -86,7 +86,8 @@ TEST(ReceiverTiming, Tests) { int64_t startTimeMs = clock.TimeInMilliseconds(); clock.AdvanceTimeMilliseconds(10); timing.StopDecodeTimer(timeStamp, startTimeMs, - clock.TimeInMilliseconds()); + clock.TimeInMilliseconds(), timing.RenderTimeMs( + timeStamp, clock.TimeInMilliseconds())); timeStamp += 90000 / 25; clock.AdvanceTimeMilliseconds(1000 / 25 - 10); timing.IncomingTimestamp(timeStamp, clock.TimeInMilliseconds());