cc: Measure compositor timing with finer granularity

cc/scheduler/compositor_timing_history.cc

Index: cc/scheduler/compositor_timing_history.cc
diff --git a/cc/scheduler/compositor_timing_history.cc b/cc/scheduler/compositor_timing_history.cc
index 7dcd9eacf03d6c70fdff64d85a026f4733018f98..ffd74c12780122f614c99ab2715fa157cf3241cc 100644
--- a/cc/scheduler/compositor_timing_history.cc
+++ b/cc/scheduler/compositor_timing_history.cc
@@ -9,17 +9,22 @@
 #include "cc/debug/rendering_stats_instrumentation.h"
 
 const size_t kDurationHistorySize = 60;
-const double kCommitAndActivationDurationEstimationPercentile = 50.0;
-const double kDrawDurationEstimationPercentile = 100.0;
-const int kDrawDurationEstimatePaddingInMicroseconds = 0;
+const double kBeginMainFrameToCommitEstimationPercentile = 50.0;

[mithro-old, 2015/06/30 07:55:49]

Why are these percentiles set to these values? Can you add a comment about how
they ended up like this?

[brianderson, 2015/06/30 17:35:15]

These were picked somewhat arbitrarily a while back and we never tuned them. We
should revisit the choices.

The ones that are 100 percentile are used to calculate the compositor deadline,
where it's really important we don't miss it.

The 50 percentile ones are used to calculate main thread response time. This
affects when we attempt to skip the BeginMainFrame and the overall smoothness of
the main thread. We should probably revisit the 50 percentile decision there.

Will add comments.

+const double kCommitToReadyToActivateEstimationPercentile = 50.0;
+const double kPrepareTilesEstimationPercentile = 100.0;
+const double kActivateEstimationPercentile = 100.0;
+const double kDrawEstimationPercentile = 100.0;
 
 namespace cc {
 
 CompositorTimingHistory::CompositorTimingHistory(
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
-    : draw_duration_history_(kDurationHistorySize),
+    : enabled_(false),
       begin_main_frame_to_commit_duration_history_(kDurationHistorySize),
-      commit_to_activate_duration_history_(kDurationHistorySize),
+      commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
+      prepare_tiles_duration_history_(kDurationHistorySize),
+      activate_duration_history_(kDurationHistorySize),
+      draw_duration_history_(kDurationHistorySize),
       rendering_stats_instrumentation_(rendering_stats_instrumentation) {
 }
 
@@ -30,40 +35,73 @@ void CompositorTimingHistory::AsValueInto(
     base::trace_event::TracedValue* state) const {

[mithro-old, 2015/06/30 07:55:49]

Can you put these in the same order as they are defined? Makes it easier to
check you haven't missed one.

[brianderson, 2015/06/30 17:35:15]

Acknowledged.

   state->SetDouble("begin_main_frame_to_commit_duration_estimate_ms",
                    BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
-  state->SetDouble("commit_to_activate_duration_estimate_ms",
-                   CommitToActivateDurationEstimate().InMillisecondsF());
+  state->SetDouble("prepare_tiles_duration_estimate_ms",
+                   PrepareTilesDurationEstimate().InMillisecondsF());
+  state->SetDouble("commit_to_ready_to_activate_duration_estimate_ms",
+                   CommitToReadyToActivateDurationEstimate().InMillisecondsF());
+  state->SetDouble("activate_duration_estimate_ms",
+                   ActivateDurationEstimate().InMillisecondsF());
   state->SetDouble("draw_duration_estimate_ms",
                    DrawDurationEstimate().InMillisecondsF());
 }
 
-base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
-  base::TimeDelta historical_estimate =
-      draw_duration_history_.Percentile(kDrawDurationEstimationPercentile);
-  base::TimeDelta padding = base::TimeDelta::FromMicroseconds(
-      kDrawDurationEstimatePaddingInMicroseconds);
-  return historical_estimate + padding;
+base::TimeTicks CompositorTimingHistory::Now() const {
+  return base::TimeTicks::Now();
+}
+
+void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
+  enabled_ = enabled;
+
+  if (enabled) {
+    begin_main_frame_sent_time_ = base::TimeTicks();
+    commit_time_ = base::TimeTicks();
+    start_prepare_tiles_time_ = base::TimeTicks();
+    start_activate_time_ = base::TimeTicks();
+    start_draw_time_ = base::TimeTicks();
+  }
 }
 
 base::TimeDelta
 CompositorTimingHistory::BeginMainFrameToCommitDurationEstimate() const {
   return begin_main_frame_to_commit_duration_history_.Percentile(
-      kCommitAndActivationDurationEstimationPercentile);
+      kBeginMainFrameToCommitEstimationPercentile);
 }
 
-base::TimeDelta CompositorTimingHistory::CommitToActivateDurationEstimate()
-    const {
-  return commit_to_activate_duration_history_.Percentile(
-      kCommitAndActivationDurationEstimationPercentile);
+base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
+  return prepare_tiles_duration_history_.Percentile(
+      kPrepareTilesEstimationPercentile);
+}
+
+base::TimeDelta
+CompositorTimingHistory::CommitToReadyToActivateDurationEstimate() const {
+  return commit_to_ready_to_activate_duration_history_.Percentile(
+      kCommitToReadyToActivateEstimationPercentile);
+}
+
+base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
+  return activate_duration_history_.Percentile(kActivateEstimationPercentile);
+}
+
+base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
+  return draw_duration_history_.Percentile(kDrawEstimationPercentile);
 }
 
 void CompositorTimingHistory::WillBeginMainFrame() {
-  begin_main_frame_sent_time_ = base::TimeTicks::Now();
+  DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
+  begin_main_frame_sent_time_ = Now();
+}
+
+void CompositorTimingHistory::BeginMainFrameAborted() {

[mithro-old, 2015/06/30 07:55:49]

Does it make sense to include aborted commits in the timing history?

+  DidCommit();
 }
 
 void CompositorTimingHistory::DidCommit() {
-  commit_complete_time_ = base::TimeTicks::Now();
+  DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
+
+  commit_time_ = Now();
+
   base::TimeDelta begin_main_frame_to_commit_duration =
-      commit_complete_time_ - begin_main_frame_sent_time_;
+      commit_time_ - begin_main_frame_sent_time_;
 
   // Before adding the new data point to the timing history, see what we would
   // have predicted for this frame. This allows us to keep track of the accuracy
@@ -72,30 +110,74 @@ void CompositorTimingHistory::DidCommit() {
       begin_main_frame_to_commit_duration,
       BeginMainFrameToCommitDurationEstimate());
 
-  begin_main_frame_to_commit_duration_history_.InsertSample(
-      begin_main_frame_to_commit_duration);
+  if (enabled_) {
+    begin_main_frame_to_commit_duration_history_.InsertSample(
+        begin_main_frame_to_commit_duration);
+  }
+
+  begin_main_frame_sent_time_ = base::TimeTicks();
+}
+
+void CompositorTimingHistory::WillPrepareTiles() {
+  DCHECK_EQ(base::TimeTicks(), start_prepare_tiles_time_);
+  start_prepare_tiles_time_ = Now();
+}
+
+void CompositorTimingHistory::DidPrepareTiles() {
+  DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
+
+  if (enabled_) {
+    base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_;
+    prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
+  }
+
+  start_prepare_tiles_time_ = base::TimeTicks();
 }
 
-void CompositorTimingHistory::DidActivateSyncTree() {
-  base::TimeDelta commit_to_activate_duration =
-      base::TimeTicks::Now() - commit_complete_time_;
+void CompositorTimingHistory::ReadyToActivate() {
+  // We only care about the first ready to activate signal
+  // after a commit.
+  if (commit_time_ == base::TimeTicks())
+    return;
+
+  base::TimeDelta time_since_commit = Now() - commit_time_;
 
   // Before adding the new data point to the timing history, see what we would
   // have predicted for this frame. This allows us to keep track of the accuracy
   // of our predictions.
   rendering_stats_instrumentation_->AddCommitToActivateDuration(
-      commit_to_activate_duration, CommitToActivateDurationEstimate());
+      time_since_commit, CommitToReadyToActivateDurationEstimate());
+
+  if (enabled_) {
+    commit_to_ready_to_activate_duration_history_.InsertSample(
+        time_since_commit);
+  }
 
-  commit_to_activate_duration_history_.InsertSample(
-      commit_to_activate_duration);
+  commit_time_ = base::TimeTicks();
 }
 
-void CompositorTimingHistory::DidStartDrawing() {
-  start_draw_time_ = base::TimeTicks::Now();
+void CompositorTimingHistory::WillActivate() {
+  DCHECK_EQ(base::TimeTicks(), start_activate_time_);
+  start_activate_time_ = Now();
 }
 
-void CompositorTimingHistory::DidFinishDrawing() {
-  base::TimeDelta draw_duration = base::TimeTicks::Now() - start_draw_time_;
+void CompositorTimingHistory::DidActivate() {
+  DCHECK_NE(base::TimeTicks(), start_activate_time_);
+  if (enabled_) {
+    base::TimeDelta activate_duration = Now() - start_activate_time_;
+    activate_duration_history_.InsertSample(activate_duration);
+  }
+  start_activate_time_ = base::TimeTicks();
+}
+
+void CompositorTimingHistory::WillDraw() {
+  DCHECK_EQ(base::TimeTicks(), start_draw_time_);
+  start_draw_time_ = Now();
+}
+
+void CompositorTimingHistory::DidDraw() {
+  DCHECK_NE(base::TimeTicks(), start_draw_time_);
+  base::TimeDelta draw_duration = Now() - start_draw_time_;
 
   // Before adding the new data point to the timing history, see what we would
   // have predicted for this frame. This allows us to keep track of the accuracy
@@ -106,7 +188,11 @@ void CompositorTimingHistory::DidFinishDrawing() {
 
   AddDrawDurationUMA(draw_duration, draw_duration_estimate);
 
-  draw_duration_history_.InsertSample(draw_duration);
+  if (enabled_) {
+    draw_duration_history_.InsertSample(draw_duration);
+  }
+
+  start_draw_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::AddDrawDurationUMA(

[mithro-old, 2015/06/30 07:55:49]

Are you planning on adding UMAs for the other ones in the future too?

[brianderson, 2015/06/30 17:35:15]

Yes. We are going to do it for PrepareTiles - will probably make sense to do it
for all of them.