cc: Measure compositor timing with finer granularity

cc/scheduler/scheduler.cc

Index: cc/scheduler/scheduler.cc
diff --git a/cc/scheduler/scheduler.cc b/cc/scheduler/scheduler.cc
index c6bbc408443e42ff2e733dfb866fe23a45a2b9b8..474b1dc9a6f01c683565d175239bed2c6f19333e 100644
--- a/cc/scheduler/scheduler.cc
+++ b/cc/scheduler/scheduler.cc
@@ -64,6 +64,7 @@ Scheduler::Scheduler(
     int layer_tree_host_id,
     const scoped_refptr<base::SingleThreadTaskRunner>& task_runner,
     scoped_ptr<BeginFrameSource> external_begin_frame_source,
+    RenderingStatsInstrumentation* rendering_stats_instrumentation,
     SchedulerFrameSourcesConstructor* frame_sources_constructor)
     : frame_source_(),
       primary_frame_source_(NULL),
@@ -76,6 +77,7 @@ Scheduler::Scheduler(
       client_(client),
       layer_tree_host_id_(layer_tree_host_id),
       task_runner_(task_runner),
+      compositor_timing_history_(rendering_stats_instrumentation),
       begin_impl_frame_deadline_mode_(
           SchedulerStateMachine::BEGIN_IMPL_FRAME_DEADLINE_MODE_NONE),
       begin_impl_frame_tracker_(BEGINFRAMETRACKER_FROM_HERE),
@@ -129,6 +131,28 @@ base::TimeTicks Scheduler::Now() const {
   return now;
 }
 
+base::TimeDelta Scheduler::BeginMainFrameToCommitDurationEstimate() const {
+  return compositor_timing_history_.BeginMainFrameToCommitDurationEstimate();
+}
+
+base::TimeDelta Scheduler::PrepareTilesDurationEstimate() const {
+  return compositor_timing_history_.PrepareTilesDurationEstimate();
+}
+
+base::TimeDelta Scheduler::PrepareTilesToReadyToActivateDurationEstimate()
+    const {
+  return compositor_timing_history_
+      .PrepareTilesToReadyToActivateDurationEstimate();
+}
+
+base::TimeDelta Scheduler::ActivateDurationEstimate() const {
+  return compositor_timing_history_.ActivateDurationEstimate();
+}
+
+base::TimeDelta Scheduler::DrawDurationEstimate() const {
+  return compositor_timing_history_.DrawDurationEstimate();
+}
+
 void Scheduler::CommitVSyncParameters(base::TimeTicks timebase,
                                       base::TimeDelta interval) {
   if (authoritative_vsync_interval_ != base::TimeDelta()) {
@@ -165,6 +189,7 @@ void Scheduler::SetCanDraw(bool can_draw) {
 }
 
 void Scheduler::NotifyReadyToActivate() {
+  compositor_timing_history_.ReadyToActivate();
   state_machine_.NotifyReadyToActivate();
   ProcessScheduledActions();
 }
@@ -242,14 +267,24 @@ void Scheduler::NotifyReadyToCommit() {
   ProcessScheduledActions();
 }
 
+void Scheduler::DidCommit() {
+  compositor_timing_history_.DidCommit();
+}
+
 void Scheduler::BeginMainFrameAborted(CommitEarlyOutReason reason) {
   TRACE_EVENT1("cc", "Scheduler::BeginMainFrameAborted", "reason",
                CommitEarlyOutReasonToString(reason));
+  compositor_timing_history_.BeginMainFrameAborted();
   state_machine_.BeginMainFrameAborted(reason);
   ProcessScheduledActions();
 }
 
+void Scheduler::WillPrepareTiles() {
+  compositor_timing_history_.WillPrepareTiles();
+}
+
 void Scheduler::DidPrepareTiles() {
+  compositor_timing_history_.DidPrepareTiles();
   state_machine_.DidPrepareTiles();
 }
 
@@ -508,7 +543,7 @@ void Scheduler::BeginImplFrameWithDeadline(const BeginFrameArgs& args) {
   advance_commit_state_task_.Cancel();
 
   BeginFrameArgs adjusted_args = args;
-  adjusted_args.deadline -= client_->DrawDurationEstimate();
+  adjusted_args.deadline -= DrawDurationEstimate();
 
   if (!state_machine_.impl_latency_takes_priority() &&
       main_thread_is_in_high_latency_mode &&
@@ -651,8 +686,16 @@ void Scheduler::PollToAdvanceCommitState() {
 }
 
 void Scheduler::DrawAndSwapIfPossible() {
+  compositor_timing_history_.WillDraw();
   DrawResult result = client_->ScheduledActionDrawAndSwapIfPossible();
   state_machine_.DidDrawIfPossibleCompleted(result);
+  compositor_timing_history_.DidDraw();
+}
+
+void Scheduler::DrawAndSwapForced() {
+  compositor_timing_history_.WillDraw();
+  client_->ScheduledActionDrawAndSwapForced();
+  compositor_timing_history_.DidDraw();
 }
 
 void Scheduler::SetDeferCommits(bool defer_commits) {
@@ -691,6 +734,7 @@ void Scheduler::ProcessScheduledActions() {
         client_->ScheduledActionAnimate();
         break;
       case SchedulerStateMachine::ACTION_SEND_BEGIN_MAIN_FRAME:
+        compositor_timing_history_.WillBeginMainFrame();
         client_->ScheduledActionSendBeginMainFrame();
         break;
       case SchedulerStateMachine::ACTION_COMMIT: {
@@ -703,7 +747,9 @@ void Scheduler::ProcessScheduledActions() {
         break;
       }
       case SchedulerStateMachine::ACTION_ACTIVATE_SYNC_TREE:
+        compositor_timing_history_.WillActivate();
         client_->ScheduledActionActivateSyncTree();
+        compositor_timing_history_.DidActivate();
         break;
       case SchedulerStateMachine::ACTION_DRAW_AND_SWAP_IF_POSSIBLE: {
         // TODO(robliao): Remove ScopedTracker below once crbug.com/461509 is
@@ -715,7 +761,7 @@ void Scheduler::ProcessScheduledActions() {
         break;
       }
       case SchedulerStateMachine::ACTION_DRAW_AND_SWAP_FORCED:
-        client_->ScheduledActionDrawAndSwapForced();
+        DrawAndSwapForced();
         break;
       case SchedulerStateMachine::ACTION_DRAW_AND_SWAP_ABORT:
         // No action is actually performed, but this allows the state machine to
@@ -723,6 +769,7 @@ void Scheduler::ProcessScheduledActions() {
         break;
       case SchedulerStateMachine::ACTION_BEGIN_OUTPUT_SURFACE_CREATION:
         client_->ScheduledActionBeginOutputSurfaceCreation();
+        compositor_timing_history_.PipelineReset();
         break;
       case SchedulerStateMachine::ACTION_PREPARE_TILES:
         client_->ScheduledActionPrepareTiles();
@@ -789,15 +836,18 @@ void Scheduler::AsValueInto(base::trace_event::TracedValue* state) const {
   state->EndDictionary();
   state->EndDictionary();
 
-  state->BeginDictionary("client_state");
-  state->SetDouble("draw_duration_estimate_ms",
-                   client_->DrawDurationEstimate().InMillisecondsF());
+  state->BeginDictionary("compositor_timing_history");
+  state->SetDouble("begin_main_frame_to_commit_duration_estimate_ms",
+                   BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
+  state->SetDouble("prepare_tiles_duration_estimate_ms",
+                   PrepareTilesDurationEstimate().InMillisecondsF());
   state->SetDouble(
-      "begin_main_frame_to_commit_duration_estimate_ms",
-      client_->BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
-  state->SetDouble(
-      "commit_to_activate_duration_estimate_ms",
-      client_->CommitToActivateDurationEstimate().InMillisecondsF());
+      "commit_to_ready_to_activate_duration_estimate_ms",
+      PrepareTilesToReadyToActivateDurationEstimate().InMillisecondsF());
+  state->SetDouble("activate_duration_estimate_ms",
+                   ActivateDurationEstimate().InMillisecondsF());
+  state->SetDouble("draw_duration_estimate_ms",
+                   DrawDurationEstimate().InMillisecondsF());
   state->EndDictionary();
 }
 
@@ -808,8 +858,9 @@ bool Scheduler::CanCommitAndActivateBeforeDeadline() const {
   // Check if the main thread computation and commit can be finished before the
   // impl thread's deadline.
   base::TimeTicks estimated_draw_time =
-      args.frame_time + client_->BeginMainFrameToCommitDurationEstimate() +
-      client_->CommitToActivateDurationEstimate();
+      args.frame_time + BeginMainFrameToCommitDurationEstimate() +
+      PrepareTilesToReadyToActivateDurationEstimate() +
+      ActivateDurationEstimate();
 
   TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
                "CanCommitAndActivateBeforeDeadline",