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 113 matching lines @@
   estimated_parent_draw_time_ = draw_time;
 }
 
 void Scheduler::SetCanStart() {
   state_machine_.SetCanStart();
   ProcessScheduledActions();
 }
 
 void Scheduler::SetVisible(bool visible) {
   state_machine_.SetVisible(visible);
+  UpdateCompositorTimingHistoryRecordingEnabled();
   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();
+  UpdateCompositorTimingHistoryRecordingEnabled();
   ProcessScheduledActions();
 }
 
 void Scheduler::DidCreateAndInitializeOutputSurface() {
   TRACE_EVENT0("cc", "Scheduler::DidCreateAndInitializeOutputSurface");
   DCHECK(!frame_source_->NeedsBeginFrames());
   DCHECK(begin_impl_frame_deadline_task_.IsCancelled());
   state_machine_.DidCreateAndInitializeOutputSurface();
+  UpdateCompositorTimingHistoryRecordingEnabled();
   ProcessScheduledActions();
 }
 
 void Scheduler::NotifyBeginMainFrameStarted() {
   TRACE_EVENT0("cc", "Scheduler::NotifyBeginMainFrameStarted");
   state_machine_.NotifyBeginMainFrameStarted();
 }
 
 base::TimeTicks Scheduler::LastBeginImplFrameTime() {
   return begin_impl_frame_tracker_.Current().frame_time;
@@ skipping 318 matching lines @@
   // TODO(robliao): Remove ScopedTracker below once crbug.com/461509 is fixed.
   tracked_objects::ScopedTracker tracking_profile1(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "461509 Scheduler::OnBeginImplFrameDeadline1"));
   state_machine_.OnBeginImplFrameDeadline();
   ProcessScheduledActions();
   FinishImplFrame();
 }
 
 void Scheduler::DrawAndSwapIfPossible() {
-  compositor_timing_history_->DidStartDrawing();
+  compositor_timing_history_->WillDraw();
   DrawResult result = client_->ScheduledActionDrawAndSwapIfPossible();
   state_machine_.DidDrawIfPossibleCompleted(result);
-  compositor_timing_history_->DidFinishDrawing();
+  compositor_timing_history_->DidDraw();
 }
 
 void Scheduler::DrawAndSwapForced() {
-  compositor_timing_history_->DidStartDrawing();
+  compositor_timing_history_->WillDraw();
   client_->ScheduledActionDrawAndSwapForced();
-  compositor_timing_history_->DidFinishDrawing();
+  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 25 matching lines @@
         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();
-        compositor_timing_history_->DidCommit();
         break;
       }
       case SchedulerStateMachine::ACTION_ACTIVATE_SYNC_TREE:
+        compositor_timing_history_->WillActivate();
         client_->ScheduledActionActivateSyncTree();
-        compositor_timing_history_->DidActivateSyncTree();
+        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;
       }
@@ skipping 61 matching lines @@
   state->BeginDictionary("begin_impl_frame_args");
   begin_impl_frame_tracker_.AsValueInto(Now(), state);
   state->EndDictionary();
   state->EndDictionary();
 
   state->BeginDictionary("compositor_timing_history");
   compositor_timing_history_->AsValueInto(state);
   state->EndDictionary();
 }
 
+void Scheduler::UpdateCompositorTimingHistoryRecordingEnabled() {
+  compositor_timing_history_->SetRecordingEnabled(
+      state_machine_.HasInitializedOutputSurface() && state_machine_.visible());
+}
+
 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 +
       compositor_timing_history_->BeginMainFrameToCommitDurationEstimate() +
-      compositor_timing_history_->CommitToActivateDurationEstimate();
+      compositor_timing_history_->CommitToReadyToActivateDurationEstimate() +
+      compositor_timing_history_->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