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
new file mode 100644
index 0000000000000000000000000000000000000000..a029439f871201760bb8463c040e3c1bd50c5e2f
--- /dev/null
+++ b/cc/scheduler/compositor_timing_history.cc
@@ -0,0 +1,173 @@
+// Copyright 2014 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/compositor_timing_history.h"
+
+#include "base/metrics/histogram.h"
+#include "cc/debug/rendering_stats_instrumentation.h"
+
+const size_t kDurationHistorySize = 60;
+const double kCommitAndActivationDurationEstimationPercentile = 50.0;
+const double kActivateDurationEstimationPercentile = 100.0;
+const double kDrawDurationEstimationPercentile = 100.0;
+
+namespace cc {
+
+CompositorTimingHistory::CompositorTimingHistory(
+    RenderingStatsInstrumentation* rendering_stats_instrumentation)
+    : begin_main_frame_to_commit_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) {
+}
+
+CompositorTimingHistory::~CompositorTimingHistory() {
+}
+
+void CompositorTimingHistory::PipelineReset() {
+  begin_main_frame_sent_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);
+}
+
+base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
+  return prepare_tiles_duration_history_.Percentile(
+      kActivateDurationEstimationPercentile);
+}
+
+base::TimeDelta
+CompositorTimingHistory::PrepareTilesToReadyToActivateDurationEstimate() const {
+  return commit_to_ready_to_activate_duration_history_.Percentile(
+      kCommitAndActivationDurationEstimationPercentile);
+}
+
+base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
+  return activate_duration_history_.Percentile(
+      kActivateDurationEstimationPercentile);
+}
+
+base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
+  return draw_duration_history_.Percentile(kDrawDurationEstimationPercentile);
+}
+
+void CompositorTimingHistory::WillBeginMainFrame() {
+  DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
+  begin_main_frame_sent_time_ = base::TimeTicks::Now();
+}
+
+void CompositorTimingHistory::BeginMainFrameAborted() {
+  DidCommit();
+}
+
+void CompositorTimingHistory::DidCommit() {
+  DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
+
+  base::TimeDelta begin_main_frame_to_commit_duration =
+      base::TimeTicks::Now() - 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
+  // of our predictions.
+  rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
+      begin_main_frame_to_commit_duration,
+      BeginMainFrameToCommitDurationEstimate());
+
+  begin_main_frame_to_commit_duration_history_.InsertSample(
+      begin_main_frame_to_commit_duration);
+
+  begin_main_frame_sent_time_ = base::TimeTicks();
+}
+
+void CompositorTimingHistory::WillPrepareTiles() {
+  start_prepare_tiles_time_ = base::TimeTicks::Now();
+}
+
+void CompositorTimingHistory::DidPrepareTiles() {
+  DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
+  base::TimeDelta prepare_tiles_duration =
+      base::TimeTicks::Now() - start_prepare_tiles_time_;
+  prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
+}
+
+void CompositorTimingHistory::ReadyToActivate() {
+  // If the start_prepare_tiles_time is 0, then a commit was ready to activate
+  // immediately.
+  base::TimeDelta time_since_prepare_tiles = base::TimeDelta();
+  if (start_prepare_tiles_time_ != base::TimeTicks())
+    base::TimeTicks::Now() - start_prepare_tiles_time_;

[picksi, 2015/06/19 13:04:28]

Is there some C++ magic going on here that I'm missing? The result of
base::TimeTicks::Now() - start_prepare_tiles_time_; seems to unused.

[brianderson, 2015/06/19 17:24:26]

That would be pretty magical. I should add some simple unit tests.

THanks for catching that.

+
+  // 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(
+      time_since_prepare_tiles,
+      PrepareTilesToReadyToActivateDurationEstimate());
+
+  commit_to_ready_to_activate_duration_history_.InsertSample(
+      time_since_prepare_tiles);
+
+  start_prepare_tiles_time_ = base::TimeTicks();
+}
+
+void CompositorTimingHistory::WillActivate() {
+  start_activate_time_ = base::TimeTicks::Now();
+}
+
+void CompositorTimingHistory::DidActivate() {
+  base::TimeDelta activate_duration =
+      base::TimeTicks::Now() - start_activate_time_;
+  activate_duration_history_.InsertSample(activate_duration);
+}
+
+void CompositorTimingHistory::WillDraw() {
+  start_draw_time_ = base::TimeTicks::Now();
+}
+
+void CompositorTimingHistory::DidDraw() {
+  base::TimeDelta draw_duration = base::TimeTicks::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
+  // of our predictions.
+  base::TimeDelta draw_duration_estimate = DrawDurationEstimate();
+  rendering_stats_instrumentation_->AddDrawDuration(draw_duration,
+                                                    draw_duration_estimate);
+
+  AddDrawDurationUMA(draw_duration, draw_duration_estimate);
+
+  draw_duration_history_.InsertSample(draw_duration);
+}
+
+void CompositorTimingHistory::AddDrawDurationUMA(
+    base::TimeDelta draw_duration,
+    base::TimeDelta draw_duration_estimate) {
+  base::TimeDelta draw_duration_overestimate;
+  base::TimeDelta draw_duration_underestimate;
+  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);
+}
+
+}  // namespace cc