Estimate draw duration in SchedulerClient

cc/trees/thread_proxy.cc

Index: cc/trees/thread_proxy.cc
diff --git a/cc/trees/thread_proxy.cc b/cc/trees/thread_proxy.cc
index 5f92c61099806816bf8b353462a724fed9ab9e85..8cb390bcd9b1330805355cd6d6a7e7bcfb3c293c 100644
--- a/cc/trees/thread_proxy.cc
+++ b/cc/trees/thread_proxy.cc
@@ -7,6 +7,7 @@
 #include "base/auto_reset.h"
 #include "base/bind.h"
 #include "base/debug/trace_event.h"
+#include "base/metrics/histogram.h"
 #include "cc/base/thread.h"
 #include "cc/input/input_handler.h"
 #include "cc/output/context_provider.h"
@@ -28,6 +29,10 @@ const double kContextRecreationTickRate = 0.03;
 // Measured in seconds.
 const double kSmoothnessTakesPriorityExpirationDelay = 0.25;
 
+const size_t kDrawDurationHistorySize = 60;
+const double kDrawDurationEstimationPercentile = 100.0;
+const int kDrawDurationEstimatePaddingInMicroseconds = 0;
+
 }  // namespace
 
 namespace cc {
@@ -67,7 +72,8 @@ ThreadProxy::ThreadProxy(LayerTreeHost* layer_tree_host,
       vsync_client_(NULL),
       inside_draw_(false),
       defer_commits_(false),
-      renew_tree_priority_on_impl_thread_pending_(false) {
+      renew_tree_priority_on_impl_thread_pending_(false),
+      draw_duration_history_(kDrawDurationHistorySize) {
   TRACE_EVENT0("cc", "ThreadProxy::ThreadProxy");
   DCHECK(IsMainThread());
   DCHECK(layer_tree_host_);
@@ -877,6 +883,8 @@ ScheduledActionDrawAndSwapResult
 ThreadProxy::ScheduledActionDrawAndSwapInternal(bool forced_draw) {
   TRACE_EVENT0("cc", "ThreadProxy::ScheduledActionDrawAndSwap");
 
+  base::TimeTicks start_time = base::TimeTicks::HighResNow();
+  base::TimeDelta draw_duration_estimate = DrawDurationEstimate();
   base::AutoReset<bool> mark_inside(&inside_draw_, true);
 
   ScheduledActionDrawAndSwapResult result;
@@ -968,9 +976,34 @@ ThreadProxy::ScheduledActionDrawAndSwapInternal(bool forced_draw) {
         base::Bind(&ThreadProxy::DidCommitAndDrawFrame, main_thread_weak_ptr_));
   }
 
-  if (draw_frame)
+  if (draw_frame) {
     CheckOutputSurfaceStatusOnImplThread();
 
+    base::TimeDelta draw_duration = base::TimeTicks::HighResNow() - start_time;
+    draw_duration_history_.InsertSample(draw_duration);
+    base::TimeDelta draw_duration_overestimate;
+    base::TimeDelta draw_duration_underestimate;

[brianderson, 2013/06/12 00:59:44]

Instead of having over/underestimate, can we just take the difference and report
that as a single number? TimeDelta is allowed to be negative.

[ajuma, 2013/06/12 01:18:11]

We need two different numbers here since UMA histograms don't support
negative-valued buckets.

+    if (draw_duration > draw_duration_estimate)
+      draw_duration_underestimate = draw_duration - draw_duration_estimate;
+    else
+      draw_duration_overestimate = draw_duration_estimate - draw_duration;
+    UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDuration",
+                               draw_duration,
+                               base::TimeDelta::FromMilliseconds(1),
+                               base::TimeDelta::FromMilliseconds(100),
+                               50);
+    UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDurationUnderestimate",
+                               draw_duration_underestimate,
+                               base::TimeDelta::FromMilliseconds(1),
+                               base::TimeDelta::FromMilliseconds(100),
+                               50);
+    UMA_HISTOGRAM_CUSTOM_TIMES("Renderer.DrawDurationOverestimate",
+                               draw_duration_overestimate,
+                               base::TimeDelta::FromMilliseconds(1),
+                               base::TimeDelta::FromMilliseconds(100),
+                               50);
+  }
+
   // Update the tile state after drawing.  This prevents manage tiles from
   // being in the critical path for getting things on screen, but still
   // makes sure that tile state is updated on a semi-regular basis.
@@ -1036,6 +1069,14 @@ void ThreadProxy::DidAnticipatedDrawTimeChange(base::TimeTicks time) {
   layer_tree_host_impl_->ResetCurrentFrameTimeForNextFrame();
 }
 
+base::TimeDelta ThreadProxy::DrawDurationEstimate() {
+  base::TimeDelta historical_estimate =
+      draw_duration_history_.Percentile(kDrawDurationEstimationPercentile);
+  base::TimeDelta padding = base::TimeDelta::FromMicroseconds(
+      kDrawDurationEstimatePaddingInMicroseconds);
+  return historical_estimate + padding;
+}
+
 void ThreadProxy::ReadyToFinalizeTextureUpdates() {
   DCHECK(IsImplThread());
   scheduler_on_impl_thread_->FinishCommit();