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

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)
     {

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<int>((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;
 }
 

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
 

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());