Log statistics of TabCapture API through UMA

content/browser/renderer_host/media/web_contents_video_capture_device.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 //
 // Implementation notes: This needs to work on a variety of hardware
 // configurations where the speed of the CPU and GPU greatly affect overall
 // performance.  Therefore, the process of capturing has been split up into a
 // pipeline of three stages.  Each stage executes on its own thread:
 //
 //   1. Capture: A bitmap is snapshotted/copied from the RenderView's backing
@@ skipping 32 matching lines @@
 #include <algorithm>
 #include <string>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback_forward.h"
 #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"
 #include "base/time.h"
 #include "content/browser/renderer_host/media/web_contents_capture_util.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/render_process_host.h"
 #include "content/public/browser/render_view_host.h"
 #include "content/public/browser/render_widget_host_view.h"
 #include "content/public/browser/web_contents.h"
@@ skipping 22 matching lines @@
   }  \
 }
 
 namespace content {
 
 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) {
   return x & static_cast<IntType>(-2);
 }
 
 // Determine a |fitted_size| that would fit within a video frame with the same
 // aspect ratio as the given source_width/height.
 void CalculateFittedSize(int source_width, int source_height,
                          int frame_width, int frame_height,
@@ skipping 65 matching lines @@
   void LookUpAndObserveWebContents();
 
   void CopyFromBackingStoreComplete(int frame_number,
                                     scoped_ptr<skia::PlatformBitmap> capture,
                                     const DoneCB& done_cb, bool success);
 
   // The "starting point" to find the capture source.
   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_;
 
   DISALLOW_COPY_AND_ASSIGN(BackingStoreCopier);
 };
 
 // Renders captures (from the backing store) into video frame buffers on a
 // separate thread.  Manages use of internally-owned video frame buffers.
 class VideoFrameRenderer {
@@ skipping 68 matching lines @@
                               const base::Time& frame_timestamp,
                               const base::Closure& done_cb);
 
   base::Thread deliver_thread_;
   SynchronizedConsumer* const consumer_;
 
   // The following keep track of and log the effective frame rate (from the
   // 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);
 };
 
 BackingStoreCopier::BackingStoreCopier(int render_process_id,
                                        int render_view_id)
     : render_process_id_(render_process_id), render_view_id_(render_view_id),
       rwh_for_testing_(NULL) {}
 
 void BackingStoreCopier::LookUpAndObserveWebContents() {
@@ skipping 54 matching lines @@
   }
 
   gfx::Size fitted_size;
   if (RenderWidgetHostView* const view = rwh->GetView()) {
     const gfx::Size& view_size = view->GetViewBounds().size();
     if (!view_size.IsEmpty()) {
       CalculateFittedSize(view_size.width(), view_size.height(),
                           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
   // it seems poor to have to allocate a new skia::PlatformBitmap as an output
   // buffer for each successive frame (rather than reuse buffers).  Perhaps
   // PlatformBitmap itself should only re-Allocate when necessary?
   skia::PlatformBitmap* const bitmap = new skia::PlatformBitmap();
   scoped_ptr<skia::PlatformBitmap> capture(bitmap);
   rwh->CopyFromBackingStore(
       gfx::Rect(),
@@ skipping 186 matching lines @@
 
 void SynchronizedConsumer::OnIncomingCapturedFrame(
     const uint8* pixels, int size, const base::Time& timestamp) {
   base::AutoLock guard(consumer_lock_);
   if (wrapped_consumer_) {
     wrapped_consumer_->OnIncomingCapturedFrame(pixels, size, timestamp);
   }
 }
 
 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();
 }
 
 void VideoFrameDeliverer::Deliver(
     int frame_number,
     const SkBitmap& frame_buffer, const base::Time& frame_timestamp,
     const base::Closure& done_cb) {
   deliver_thread_.message_loop()->PostTask(
       FROM_HERE,
       base::Bind(&VideoFrameDeliverer::DeliverOnDeliverThread,
                  base::Unretained(this),
                  frame_number, base::ConstRef(frame_buffer), frame_timestamp,
                  done_cb));
 }
 
 void VideoFrameDeliverer::DeliverOnDeliverThread(
     int frame_number,
     const SkBitmap& frame_buffer, const base::Time& frame_timestamp,
     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.
   // Note: The consumer will do an ARGB-->YUV conversion in this callback,
   // blocking the current thread for a bit.
   SkAutoLockPixels frame_buffer_locker(frame_buffer);
   consumer_->OnIncomingCapturedFrame(
       static_cast<const uint8*>(frame_buffer.getPixels()),
       frame_buffer.getSize(),
       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;
-      }
     }
   }
 
   // All done.
   done_cb.Run();
 }
 
 }  // namespace
 
 // The "meat" of the video capture implementation, which is a ref-counted class.
@@ skipping 46 matching lines @@
   // Stops capturing and notifies consumer_ of an error state.
   void Error();
 
   // Schedules the next frame capture off of the system clock, skipping frames
   // to catch-up if necessary.
   void ScheduleNextFrameCapture();
 
   // 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);
   void RenderComplete(int frame_number,
                       const base::Time& capture_time,
                       const SkBitmap* frame_buffer);
   void DeliverComplete(const SkBitmap* frame_buffer);
 
   // Specialized RefCounted traits for CaptureMachine, so that operator delete
   // is called from an "outside" thread.  See comments for "traits" in
@@ skipping 224 matching lines @@
   if (state_ != kCapturing) {
     return;
   }
 
   if (!is_snapshotting_) {
     is_snapshotting_ = true;
 
     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_),
                    frame_number_, settings_.width, settings_.height, done_cb);
     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, start_cb);
   }
 
   ScheduleNextFrameCapture();
 }
 
 void CaptureMachine::SnapshotComplete(int frame_number,
+                                      base::Time start_time,
                                       BackingStoreCopier::Result result,
                                       scoped_ptr<skia::PlatformBitmap> capture,
                                       const base::Time& capture_time) {
   DCHECK_EQ(manager_thread_.message_loop(), MessageLoop::current());
 
   DCHECK(is_snapshotting_);
   is_snapshotting_ = false;
 
   if (state_ != kCapturing) {
     return;
   }
 
   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);
         DCHECK(!capture_time.is_null());
         renderer_.Render(
             frame_number,
             capture.Pass(),
             settings_.width, settings_.height,
             media::BindToLoop(manager_thread_.message_loop_proxy(),
                               base::Bind(&CaptureMachine::RenderComplete, this,
@@ skipping 103 matching lines @@
   capturer_->SetConsumer(NULL);
   capturer_->DeAllocate();
 }
 
 const media::VideoCaptureDevice::Name&
 WebContentsVideoCaptureDevice::device_name() {
   return device_name_;
 }
 
 }  // namespace content