cc: Measure compositor timing with finer granularity

cc/scheduler/scheduler.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/scheduler/scheduler.h"
 
 #include <algorithm>
 
 #include "base/auto_reset.h"
 #include "base/logging.h"
@@ skipping 46 matching lines @@
       BackToBackBeginFrameSource::Create(scheduler->task_runner_.get());
   return scheduler->unthrottled_frame_source_internal_.get();
 }
 
 Scheduler::Scheduler(
     SchedulerClient* client,
     const SchedulerSettings& scheduler_settings,
     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),
       primary_frame_source_internal_(external_begin_frame_source.Pass()),
       vsync_observer_(NULL),
       authoritative_vsync_interval_(base::TimeDelta()),
       last_vsync_timebase_(base::TimeTicks()),
       throttle_frame_production_(false),
       settings_(scheduler_settings),
       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),
       state_machine_(scheduler_settings),
       inside_process_scheduled_actions_(false),
       inside_action_(SchedulerStateMachine::ACTION_NONE),
       weak_factory_(this) {
   TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
                "Scheduler::Scheduler",
                "settings",
@@ skipping 33 matching lines @@
 
 base::TimeTicks Scheduler::Now() const {
   base::TimeTicks now = base::TimeTicks::Now();
   TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.now"),
                "Scheduler::Now",
                "now",
                now);
   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()) {
     interval = authoritative_vsync_interval_;
   } else if (interval == base::TimeDelta()) {
     // TODO(brianderson): We should not be receiving 0 intervals.
     interval = BeginFrameArgs::DefaultInterval();
   }
 
   last_vsync_timebase_ = timebase;
@@ skipping 16 matching lines @@
   state_machine_.SetVisible(visible);
   ProcessScheduledActions();
 }
 
 void Scheduler::SetCanDraw(bool can_draw) {
   state_machine_.SetCanDraw(can_draw);
   ProcessScheduledActions();
 }
 
 void Scheduler::NotifyReadyToActivate() {
+  compositor_timing_history_.ReadyToActivate();
   state_machine_.NotifyReadyToActivate();
   ProcessScheduledActions();
 }
 
 void Scheduler::NotifyReadyToDraw() {
   // Future work might still needed for crbug.com/352894.
   state_machine_.NotifyReadyToDraw();
   ProcessScheduledActions();
 }
 
@@ skipping 57 matching lines @@
   state_machine_.SetImplLatencyTakesPriority(impl_latency_takes_priority);
   ProcessScheduledActions();
 }
 
 void Scheduler::NotifyReadyToCommit() {
   TRACE_EVENT0("cc", "Scheduler::NotifyReadyToCommit");
   state_machine_.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();
 }
 
 void Scheduler::DidLoseOutputSurface() {
   TRACE_EVENT0("cc", "Scheduler::DidLoseOutputSurface");
   begin_retro_frame_args_.clear();
   begin_retro_frame_task_.Cancel();
   state_machine_.DidLoseOutputSurface();
   ProcessScheduledActions();
 }
@@ skipping 238 matching lines @@
       state_machine_.MainThreadIsInHighLatencyMode();
   TRACE_EVENT2("cc,benchmark", "Scheduler::BeginImplFrame", "args",
                args.AsValue(), "main_thread_is_high_latency",
                main_thread_is_in_high_latency_mode);
   TRACE_COUNTER1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler"),
                  "MainThreadLatency", main_thread_is_in_high_latency_mode);
 
   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 &&
       CanCommitAndActivateBeforeDeadline()) {
     state_machine_.SetSkipNextBeginMainFrameToReduceLatency();
   }
 
   BeginImplFrame(adjusted_args);
 
   // The deadline will be scheduled in ProcessScheduledActions.
@@ skipping 122 matching lines @@
 }
 
 
 void Scheduler::PollToAdvanceCommitState() {
   TRACE_EVENT0("cc", "Scheduler::PollToAdvanceCommitState");
   advance_commit_state_task_.Cancel();
   ProcessScheduledActions();
 }
 
 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) {
   TRACE_EVENT1("cc", "Scheduler::SetDeferCommits",
                 "defer_commits",
                 defer_commits);
   state_machine_.SetDeferCommits(defer_commits);
   ProcessScheduledActions();
 }
 
@@ skipping 18 matching lines @@
     state_machine_.UpdateState(action);
     base::AutoReset<SchedulerStateMachine::Action>
         mark_inside_action(&inside_action_, action);
     switch (action) {
       case SchedulerStateMachine::ACTION_NONE:
         break;
       case SchedulerStateMachine::ACTION_ANIMATE:
         client_->ScheduledActionAnimate();
         break;
       case SchedulerStateMachine::ACTION_SEND_BEGIN_MAIN_FRAME:
+        compositor_timing_history_.WillBeginMainFrame();
         client_->ScheduledActionSendBeginMainFrame();
         break;
       case SchedulerStateMachine::ACTION_COMMIT: {
         // TODO(robliao): Remove ScopedTracker below once crbug.com/461509 is
         // fixed.
         tracked_objects::ScopedTracker tracking_profile4(
             FROM_HERE_WITH_EXPLICIT_FUNCTION(
                 "461509 Scheduler::ProcessScheduledActions4"));
         client_->ScheduledActionCommit();
         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
         // fixed.
         tracked_objects::ScopedTracker tracking_profile6(
             FROM_HERE_WITH_EXPLICIT_FUNCTION(
                 "461509 Scheduler::ProcessScheduledActions6"));
         DrawAndSwapIfPossible();
         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
         // advance out of its waiting to draw state without actually drawing.
         break;
       case SchedulerStateMachine::ACTION_BEGIN_OUTPUT_SURFACE_CREATION:
         client_->ScheduledActionBeginOutputSurfaceCreation();
+        compositor_timing_history_.PipelineReset();
         break;
       case SchedulerStateMachine::ACTION_PREPARE_TILES:
         client_->ScheduledActionPrepareTiles();
         break;
       case SchedulerStateMachine::ACTION_INVALIDATE_OUTPUT_SURFACE: {
         client_->ScheduledActionInvalidateOutputSurface();
         break;
       }
     }
   } while (action != SchedulerStateMachine::ACTION_NONE);
@@ skipping 46 matching lines @@
                     !begin_impl_frame_deadline_task_.IsCancelled());
   state->SetBoolean("advance_commit_state_task",
                     !advance_commit_state_task_.IsCancelled());
   state->SetString("inside_action",
                    SchedulerStateMachine::ActionToString(inside_action_));
   state->BeginDictionary("begin_impl_frame_args");
   begin_impl_frame_tracker_.AsValueInto(Now(), state);
   state->EndDictionary();
   state->EndDictionary();
 
-  state->BeginDictionary("client_state");
+  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(
+      "commit_to_ready_to_activate_duration_estimate_ms",
+      PrepareTilesToReadyToActivateDurationEstimate().InMillisecondsF());
+  state->SetDouble("activate_duration_estimate_ms",
+                   ActivateDurationEstimate().InMillisecondsF());
   state->SetDouble("draw_duration_estimate_ms",
-                   client_->DrawDurationEstimate().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());
+                   DrawDurationEstimate().InMillisecondsF());
   state->EndDictionary();
 }
 
 bool Scheduler::CanCommitAndActivateBeforeDeadline() const {
   BeginFrameArgs args =
       begin_impl_frame_tracker_.DangerousMethodCurrentOrLast();
 
   // 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",
                "time_left_after_drawing_ms",
                (args.deadline - estimated_draw_time).InMillisecondsF(), "state",
                AsValue());
 
   return estimated_draw_time < args.deadline;
 }
 
 bool Scheduler::IsBeginMainFrameSentOrStarted() const {
   return (state_machine_.commit_state() ==
               SchedulerStateMachine::COMMIT_STATE_BEGIN_MAIN_FRAME_SENT ||
           state_machine_.commit_state() ==
               SchedulerStateMachine::COMMIT_STATE_BEGIN_MAIN_FRAME_STARTED);
 }
 
 }  // namespace cc