Estimate draw duration in SchedulerClient

cc/trees/thread_proxy.cc

 // Copyright 2011 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.
 
 #include "cc/trees/thread_proxy.h"
 
 #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"
 #include "cc/output/output_surface.h"
 #include "cc/quads/draw_quad.h"
 #include "cc/resources/prioritized_resource_manager.h"
 #include "cc/scheduler/delay_based_time_source.h"
 #include "cc/scheduler/frame_rate_controller.h"
 #include "cc/scheduler/scheduler.h"
 #include "cc/scheduler/vsync_time_source.h"
 #include "cc/trees/layer_tree_host.h"
 #include "cc/trees/layer_tree_impl.h"
 
 namespace {
 
 // Measured in seconds.
 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 {
 
 scoped_ptr<Proxy> ThreadProxy::Create(LayerTreeHost* layer_tree_host,
                                       scoped_ptr<Thread> impl_thread) {
   return make_scoped_ptr(
       new ThreadProxy(layer_tree_host, impl_thread.Pass())).PassAs<Proxy>();
 }
 
@@ skipping 19 matching lines @@
       next_frame_is_newly_committed_frame_on_impl_thread_(false),
       throttle_frame_production_(
           layer_tree_host->settings().throttle_frame_production),
       begin_frame_scheduling_enabled_(
           layer_tree_host->settings().begin_frame_scheduling_enabled),
       using_synchronous_renderer_compositor_(
           layer_tree_host->settings().using_synchronous_renderer_compositor),
       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_);
 }
 
 ThreadProxy::~ThreadProxy() {
   TRACE_EVENT0("cc", "ThreadProxy::~ThreadProxy");
   DCHECK(IsMainThread());
   DCHECK(!started_);
 }
@@ skipping 789 matching lines @@
   DCHECK(IsImplThread());
   Proxy::MainThread()->PostTask(
       base::Bind(&ThreadProxy::CreateAndInitializeOutputSurface,
                  main_thread_weak_ptr_));
 }
 
 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;
   result.did_draw = false;
   result.did_swap = false;
   DCHECK(IsImplThread());
   DCHECK(layer_tree_host_impl_.get());
   if (!layer_tree_host_impl_)
     return result;
 
@@ skipping 71 matching lines @@
       DidSwapUseIncompleteTileOnImplThread();
   }
 
   // Tell the main thread that the the newly-commited frame was drawn.
   if (next_frame_is_newly_committed_frame_on_impl_thread_) {
     next_frame_is_newly_committed_frame_on_impl_thread_ = false;
     Proxy::MainThread()->PostTask(
         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.
   if (layer_tree_host_impl_->settings().impl_side_painting)
     layer_tree_host_impl_->ManageTiles();
 
   return result;
 }
 
 void ThreadProxy::AcquireLayerTextures() {
@@ skipping 45 matching lines @@
   return ScheduledActionDrawAndSwapInternal(true);
 }
 
 void ThreadProxy::DidAnticipatedDrawTimeChange(base::TimeTicks time) {
   if (current_resource_update_controller_on_impl_thread_)
     current_resource_update_controller_on_impl_thread_
         ->PerformMoreUpdates(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();
 }
 
 void ThreadProxy::DidCommitAndDrawFrame() {
   DCHECK(IsMainThread());
   if (!layer_tree_host_)
     return;
   layer_tree_host_->DidCommitAndDrawFrame();
@@ skipping 334 matching lines @@
       !layer_tree_host_impl_->pending_tree()) {
     TRACE_EVENT_INSTANT0("cc", "ReleaseCommitbyActivation",
                          TRACE_EVENT_SCOPE_THREAD);
     DCHECK(layer_tree_host_impl_->settings().impl_side_painting);
     completion_event_for_commit_held_on_tree_activation_->Signal();
     completion_event_for_commit_held_on_tree_activation_ = NULL;
   }
 }
 
 }  // namespace cc