Log statistics of TabCapture API through UMA

content/browser/renderer_host/media/web_contents_video_capture_device.cc

Index: content/browser/renderer_host/media/web_contents_video_capture_device.cc
diff --git a/content/browser/renderer_host/media/web_contents_video_capture_device.cc b/content/browser/renderer_host/media/web_contents_video_capture_device.cc
index d9b8b7f9708a6eceb76f1a0b225c33c7fd320181..5203de4b9daf5131d10c9c6814c31ca5a8685bb7 100644
--- a/content/browser/renderer_host/media/web_contents_video_capture_device.cc
+++ b/content/browser/renderer_host/media/web_contents_video_capture_device.cc
@@ -50,6 +50,7 @@
 #include "base/debug/trace_event.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
+#include "base/metrics/histogram.h"
 #include "base/stringprintf.h"
 #include "base/synchronization/lock.h"
 #include "base/threading/thread.h"
@@ -92,6 +93,10 @@ namespace {
 const int kMinFrameWidth = 2;
 const int kMinFrameHeight = 2;
 
+// Report % of frame drop for the following frame interval. That accounts for
+// about 5 minutes of frames.
+const int kFrameDropReportInterval = 9000;

[miu, 2012/12/14 23:28:35]

I think you can remove this (see comments below).

[Alpha Left Google, 2013/01/04 00:00:38]

Done.

+
 // Returns the nearest even integer closer to zero.
 template<typename IntType>
 IntType MakeEven(IntType x) {
@@ -177,6 +182,9 @@ class BackingStoreCopier : public WebContentsObserver {
   const int render_process_id_;
   const int render_view_id_;
 
+  // Last known RenderView size.
+  gfx::Size last_view_size_;
+
   // If the following is NULL (normal behavior), the implementation should
   // access RenderWidgetHost via web_contents().
   RenderWidgetHost* rwh_for_testing_;
@@ -265,6 +273,8 @@ class VideoFrameDeliverer {
   // deliver stage) whenever verbose logging is turned on.
   base::Time last_frame_rate_log_time_;
   int count_frames_rendered_;
+  int count_frames_missed_;
+  int last_frame_number_;
 
   DISALLOW_COPY_AND_ASSIGN(VideoFrameDeliverer);
 };
@@ -339,6 +349,14 @@ void BackingStoreCopier::StartCopy(int frame_number,
                           desired_width, desired_height,
                           &fitted_size);
     }
+    if (view_size != last_view_size_) {
+      last_view_size_ = view_size;
+
+      // Measure the number of kilopixels.
+      UMA_HISTOGRAM_COUNTS_10000(
+          "TabCapture.ViewKiloPixels",

[miu, 2012/12/14 23:28:35]

Since a sample is only recorded when the size changes, should we name this
something like TabCapture.ViewChangeKiloPixels?

[Alpha Left Google, 2013/01/04 00:00:38]

Done.

+          view_size.width() * view_size.height() / 1024);
+    }
   }
 
   // TODO(miu): Look into tweaking the interface to CopyFromBackingStore, since
@@ -545,7 +563,10 @@ void SynchronizedConsumer::OnIncomingCapturedFrame(
 }
 
 VideoFrameDeliverer::VideoFrameDeliverer(SynchronizedConsumer* consumer)
-    : deliver_thread_("WebContentsVideo_DeliverThread"), consumer_(consumer) {
+    : deliver_thread_("WebContentsVideo_DeliverThread"),
+      consumer_(consumer),
+      count_frames_missed_(0),
+      last_frame_number_(0) {
   DCHECK(consumer_);
   deliver_thread_.Start();
 }
@@ -568,6 +589,20 @@ void VideoFrameDeliverer::DeliverOnDeliverThread(
     const base::Closure& done_cb) {
   DCHECK_EQ(deliver_thread_.message_loop(), MessageLoop::current());
 
+  // Count the number of frame drops based on non-consecutive frame numbers.
+  if (frame_number > last_frame_number_)
+    count_frames_missed_ += frame_number - last_frame_number_ - 1;
+
+  if (frame_number % kFrameDropReportInterval ==

[miu, 2012/12/14 23:28:35]

Rather than do this mod kFrameDropReportInterval stuff, why not just record the
FrameDropPercentage below (i.e., where TabCaputre.FrameRate is recorded)?

Then, instead of incrementing count_frames_missed_, you can also easily
calculate it as:

  const int count_frames_dropped =
      frame_number_ - last_frame_number_ - count_frames_rendered_
  DCHECK_LE(0, count_frames_dropped);
  last_frame_number_ = frame_number_;  // Update last_frame_number_ where
count_frames_rendered_ = 0;

[Alpha Left Google, 2013/01/04 00:00:38]

Done.

+      kFrameDropReportInterval - 1) {
+    // Count the percentage of frames dropped in the last period.
+    UMA_HISTOGRAM_PERCENTAGE(
+        "TabCapture.FrameDropPercentage",
+        count_frames_missed_ * 100 / kFrameDropReportInterval);

[miu, 2012/12/14 23:28:35]

What if the frames missed is 0.9%?  It seems we'd want to know that (e.g., on
fast hardware).  UMA_HISTOGRAM_COUNTS_10000 would let you do basis points for
more precision.

Also/Or, consider rounding to int: static_cast<int>(<<calculation>> + 0.5)

[Alpha Left Google, 2013/01/04 00:00:38]

Done.

+    count_frames_missed_ = 0;
+  }
+  last_frame_number_ = frame_number;
+
   TRACE_EVENT1("mirroring", "DeliverFrame", "frame_number", frame_number);
 
   // Send the frame to the consumer.
@@ -580,24 +615,23 @@ void VideoFrameDeliverer::DeliverOnDeliverThread(
       frame_timestamp);
 
   // Log frame rate, if verbose logging is turned on.
-  if (VLOG_IS_ON(1)) {
-    static const base::TimeDelta kFrameRateLogInterval =
-        base::TimeDelta::FromSeconds(5);
-    const base::Time& now = base::Time::Now();
-    if (last_frame_rate_log_time_.is_null()) {
+  static const base::TimeDelta kFrameRateLogInterval =
+      base::TimeDelta::FromSeconds(10);
+  const base::Time& now = base::Time::Now();
+  if (last_frame_rate_log_time_.is_null()) {
+    last_frame_rate_log_time_ = now;
+    count_frames_rendered_ = 0;
+  } else {
+    ++count_frames_rendered_;
+    const base::TimeDelta elapsed = now - last_frame_rate_log_time_;
+    if (elapsed >= kFrameRateLogInterval) {
+      const int measured_fps =

[miu, 2012/12/14 23:28:35]

IMHO, you're going to want more precision here.  Suggest you make measured_fps
double like it was, or consider changing this metric to frames-per-minute or
some such.

[Alpha Left Google, 2013/01/04 00:00:38]

I think a rough number is enough, 29 or 30 are both fine.

+          count_frames_rendered_ / elapsed.InSecondsF();
+      UMA_HISTOGRAM_COUNTS("TabCapture.FrameRate", measured_fps);

[miu, 2012/12/14 23:28:35]

Ditto on considering rounding the value (assuming you make measured_fps a
double).  You may want to increase the precision being recorded: Meaning, is
29.0 vs. 29.5 vs 30.0 FPS something we want measured?

+      VLOG(1) << "Current measured frame rate for CaptureMachine@" << this
+              << " is " << measured_fps << " FPS.";
       last_frame_rate_log_time_ = now;
       count_frames_rendered_ = 0;
-    } else {
-      ++count_frames_rendered_;
-      const base::TimeDelta elapsed = now - last_frame_rate_log_time_;
-      if (elapsed >= kFrameRateLogInterval) {
-        const double measured_fps =
-            count_frames_rendered_ / elapsed.InSecondsF();
-        VLOG(1) << "Current measured frame rate for CaptureMachine@" << this
-                << " is " << measured_fps << " FPS.";
-        last_frame_rate_log_time_ = now;
-        count_frames_rendered_ = 0;
-      }
     }
   }
 
@@ -664,6 +698,7 @@ class CaptureMachine
   // The glue between the pipeline stages.
   void StartSnapshot();
   void SnapshotComplete(int frame_number,
+                        base::Time start_time,

[miu, 2012/12/14 23:28:35]

Should be const ref type.

[Alpha Left Google, 2013/01/04 00:00:38]

Done.

                         BackingStoreCopier::Result result,
                         scoped_ptr<skia::PlatformBitmap> capture,
                         const base::Time& capture_time);
@@ -908,7 +943,7 @@ void CaptureMachine::StartSnapshot() {
     const BackingStoreCopier::DoneCB& done_cb =
         media::BindToLoop(manager_thread_.message_loop_proxy(),
                           base::Bind(&CaptureMachine::SnapshotComplete, this,
-                                     frame_number_));
+                                     frame_number_, base::Time::Now()));
     const base::Closure& start_cb =
         base::Bind(&BackingStoreCopier::StartCopy,
                    base::Unretained(&copier_),
@@ -920,6 +955,7 @@ void CaptureMachine::StartSnapshot() {
 }
 
 void CaptureMachine::SnapshotComplete(int frame_number,
+                                      base::Time start_time,
                                       BackingStoreCopier::Result result,
                                       scoped_ptr<skia::PlatformBitmap> capture,
                                       const base::Time& capture_time) {
@@ -934,6 +970,8 @@ void CaptureMachine::SnapshotComplete(int frame_number,
 
   switch (result) {
     case BackingStoreCopier::OK:
+      UMA_HISTOGRAM_TIMES("TabCapture.SnapshotTime",
+                          base::Time::Now() - start_time);
       if (num_renders_pending_ <= 1) {
         ++num_renders_pending_;
         DCHECK(capture);