cc: CompositorTimingHistory throughput UMAs

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 e82356baeb412e8c427415134fef4dbb55b449d4..d21696dca6ae3afb3894babbe4cbfb3e222ab411 100644
--- a/cc/scheduler/compositor_timing_history.cc
+++ b/cc/scheduler/compositor_timing_history.cc
@@ -14,6 +14,14 @@ class CompositorTimingHistory::UMAReporter {
  public:
   virtual ~UMAReporter() {}
 
+  // Throughput measurements
+  virtual void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) = 0;
+  virtual void AddBeginMainFrameIntervalNotCritical(
+      base::TimeDelta interval) = 0;
+  virtual void AddCommitInterval(base::TimeDelta interval) = 0;
+  virtual void AddDrawInterval(base::TimeDelta interval) = 0;
+
+  // Latency measurements
   virtual void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
                                                  base::TimeDelta estimate,
                                                  bool affects_estimate) = 0;
@@ -130,6 +138,26 @@ class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~RendererUMAReporter() override {}
 
+  void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Renderer.BeginMainFrameIntervalCritical", interval);
+  }
+
+  void AddBeginMainFrameIntervalNotCritical(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Renderer.BeginMainFrameIntervalNotCritical", interval);
+  }
+
+  void AddCommitInterval(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Renderer.CommitInterval",
+                                      interval);
+  }
+
+  void AddDrawInterval(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Renderer.DrawInterval",
+                                      interval);
+  }
+
   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
                                          base::TimeDelta estimate,
                                          bool affects_estimate) override {
@@ -191,6 +219,26 @@ class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~BrowserUMAReporter() override {}
 
+  void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Browser.BeginMainFrameIntervalCritical", interval);
+  }
+
+  void AddBeginMainFrameIntervalNotCritical(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Browser.BeginMainFrameIntervalNotCritical", interval);
+  }
+
+  void AddCommitInterval(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Browser.CommitInterval",
+                                      interval);
+  }
+
+  void AddDrawInterval(base::TimeDelta interval) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Browser.DrawInterval",
+                                      interval);
+  }
+
   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
                                          base::TimeDelta estimate,
                                          bool affects_estimate) override {
@@ -251,6 +299,11 @@ class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
 class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~NullUMAReporter() override {}
+  void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {}
+  void AddBeginMainFrameIntervalNotCritical(base::TimeDelta interval) override {
+  }
+  void AddCommitInterval(base::TimeDelta interval) override {}
+  void AddDrawInterval(base::TimeDelta interval) override {}
   void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
                                          base::TimeDelta estimate,
                                          bool affects_estimate) override {}
@@ -283,6 +336,10 @@ CompositorTimingHistory::CompositorTimingHistory(
     UMACategory uma_category,
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
     : enabled_(false),
+      did_send_begin_main_frame_(false),
+      begin_main_frame_needed_continuously_(false),
+      begin_main_frame_committing_continuously_(false),
+      compositor_drawing_continuously_(false),
       begin_main_frame_sent_to_commit_duration_history_(kDurationHistorySize),
       begin_main_frame_queue_duration_critical_history_(kDurationHistorySize),
       begin_main_frame_queue_duration_not_critical_history_(
@@ -338,6 +395,28 @@ void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
   enabled_ = enabled;
 }
 
+void CompositorTimingHistory::SetBeginMainFrameNeededContinuously(bool active) {
+  if (active == begin_main_frame_needed_continuously_)
+    return;
+  begin_main_frame_end_time_prev_ = base::TimeTicks();
+  begin_main_frame_needed_continuously_ = active;
+}
+
+void CompositorTimingHistory::SetBeginMainFrameCommittingContinuously(
+    bool active) {
+  if (active == begin_main_frame_committing_continuously_)
+    return;
+  new_active_tree_draw_end_time_prev_ = base::TimeTicks();
+  begin_main_frame_committing_continuously_ = active;
+}
+
+void CompositorTimingHistory::SetCompositorDrawingContinuously(bool active) {
+  if (active == compositor_drawing_continuously_)
+    return;
+  draw_end_time_prev_ = base::TimeTicks();
+  compositor_drawing_continuously_ = active;
+}
+
 base::TimeDelta
 CompositorTimingHistory::BeginMainFrameToCommitDurationEstimate() const {
   return begin_main_frame_sent_to_commit_duration_history_.Percentile(
@@ -382,10 +461,40 @@ base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
   return draw_duration_history_.Percentile(kDrawEstimationPercentile);
 }
 
+void CompositorTimingHistory::WillBeginImplFrame(
+    bool new_active_tree_is_likely) {
+  // The check for whether a BeginMainFrame was sent anytime between two
+  // BeginImplFrames protects us from not detecting a fast main thread that
+  // does all it's work and goes idle in between BeginImplFrames.
+  // For example, this may happen if an animation is being driven with
+  // setInterval(17) or if input events just happen to arrive in the
+  // middle of every frame.
+  if (!new_active_tree_is_likely && !did_send_begin_main_frame_) {
+    SetBeginMainFrameNeededContinuously(false);
+    SetBeginMainFrameCommittingContinuously(false);
+  }
+
+  did_send_begin_main_frame_ = false;
+}
+
+void CompositorTimingHistory::WillFinishImplFrame(bool needs_redraw) {
+  if (!needs_redraw)
+    SetCompositorDrawingContinuously(false);
+}
+
+void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
+  SetBeginMainFrameNeededContinuously(false);
+  SetBeginMainFrameCommittingContinuously(false);
+  SetCompositorDrawingContinuously(false);
+}
+
 void CompositorTimingHistory::WillBeginMainFrame(bool on_critical_path) {
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
   begin_main_frame_on_critical_path_ = on_critical_path;
   begin_main_frame_sent_time_ = Now();
+
+  did_send_begin_main_frame_ = true;
+  SetBeginMainFrameNeededContinuously(true);
 }
 
 void CompositorTimingHistory::BeginMainFrameStarted(
@@ -396,13 +505,19 @@ void CompositorTimingHistory::BeginMainFrameStarted(
 }
 
 void CompositorTimingHistory::BeginMainFrameAborted() {
-  DidCommit();
+  SetBeginMainFrameCommittingContinuously(false);
+  DidBeginMainFrame();
 }
 
 void CompositorTimingHistory::DidCommit() {
+  SetBeginMainFrameCommittingContinuously(true);
+  DidBeginMainFrame();
+}
+
+void CompositorTimingHistory::DidBeginMainFrame() {
   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 
-  commit_time_ = Now();
+  begin_main_frame_end_time_ = Now();
 
   // If the BeginMainFrame start time isn't know, assume it was immediate
   // for scheduling purposes, but don't report it for UMA to avoid skewing
@@ -413,11 +528,11 @@ void CompositorTimingHistory::DidCommit() {
     begin_main_frame_start_time_ = begin_main_frame_sent_time_;
 
   base::TimeDelta begin_main_frame_sent_to_commit_duration =
-      commit_time_ - begin_main_frame_sent_time_;
+      begin_main_frame_end_time_ - begin_main_frame_sent_time_;
   base::TimeDelta begin_main_frame_queue_duration =
       begin_main_frame_start_time_ - begin_main_frame_sent_time_;
   base::TimeDelta begin_main_frame_start_to_commit_duration =
-      commit_time_ - begin_main_frame_start_time_;
+      begin_main_frame_end_time_ - begin_main_frame_start_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
@@ -458,34 +573,46 @@ void CompositorTimingHistory::DidCommit() {
         begin_main_frame_start_to_commit_duration);
   }
 
+  if (begin_main_frame_needed_continuously_) {
+    if (!begin_main_frame_end_time_prev_.is_null()) {
+      base::TimeDelta commit_interval =
+          begin_main_frame_end_time_ - begin_main_frame_end_time_prev_;
+      if (begin_main_frame_on_critical_path_)
+        uma_reporter_->AddBeginMainFrameIntervalCritical(commit_interval);
+      else
+        uma_reporter_->AddBeginMainFrameIntervalNotCritical(commit_interval);
+    }
+    begin_main_frame_end_time_prev_ = begin_main_frame_end_time_;
+  }
+
   begin_main_frame_sent_time_ = base::TimeTicks();
   begin_main_frame_start_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::WillPrepareTiles() {
-  DCHECK_EQ(base::TimeTicks(), start_prepare_tiles_time_);
-  start_prepare_tiles_time_ = Now();
+  DCHECK_EQ(base::TimeTicks(), prepare_tiles_start_time_);
+  prepare_tiles_start_time_ = Now();
 }
 
 void CompositorTimingHistory::DidPrepareTiles() {
-  DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
+  DCHECK_NE(base::TimeTicks(), prepare_tiles_start_time_);
 
-  base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_;
+  base::TimeDelta prepare_tiles_duration = Now() - prepare_tiles_start_time_;
   uma_reporter_->AddPrepareTilesDuration(
       prepare_tiles_duration, PrepareTilesDurationEstimate(), enabled_);
   if (enabled_)
     prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
 
-  start_prepare_tiles_time_ = base::TimeTicks();
+  prepare_tiles_start_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::ReadyToActivate() {
   // We only care about the first ready to activate signal
   // after a commit.
-  if (commit_time_ == base::TimeTicks())
+  if (begin_main_frame_end_time_ == base::TimeTicks())
     return;
 
-  base::TimeDelta time_since_commit = Now() - commit_time_;
+  base::TimeDelta time_since_commit = Now() - begin_main_frame_end_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
@@ -503,34 +630,35 @@ void CompositorTimingHistory::ReadyToActivate() {
         time_since_commit);
   }
 
-  commit_time_ = base::TimeTicks();
+  begin_main_frame_end_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::WillActivate() {
-  DCHECK_EQ(base::TimeTicks(), start_activate_time_);
-  start_activate_time_ = Now();
+  DCHECK_EQ(base::TimeTicks(), activate_start_time_);
+  activate_start_time_ = Now();
 }
 
 void CompositorTimingHistory::DidActivate() {
-  DCHECK_NE(base::TimeTicks(), start_activate_time_);
-  base::TimeDelta activate_duration = Now() - start_activate_time_;
+  DCHECK_NE(base::TimeTicks(), activate_start_time_);
+  base::TimeDelta activate_duration = Now() - activate_start_time_;
 
   uma_reporter_->AddActivateDuration(activate_duration,
                                      ActivateDurationEstimate(), enabled_);
   if (enabled_)
     activate_duration_history_.InsertSample(activate_duration);
 
-  start_activate_time_ = base::TimeTicks();
+  activate_start_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::WillDraw() {
-  DCHECK_EQ(base::TimeTicks(), start_draw_time_);
-  start_draw_time_ = Now();
+  DCHECK_EQ(base::TimeTicks(), draw_start_time_);
+  draw_start_time_ = Now();
 }
 
-void CompositorTimingHistory::DidDraw() {
-  DCHECK_NE(base::TimeTicks(), start_draw_time_);
-  base::TimeDelta draw_duration = Now() - start_draw_time_;
+void CompositorTimingHistory::DidDraw(bool used_new_active_tree) {
+  DCHECK_NE(base::TimeTicks(), draw_start_time_);
+  base::TimeTicks draw_end_time = Now();
+  base::TimeDelta draw_duration = draw_end_time - draw_start_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
@@ -545,7 +673,23 @@ void CompositorTimingHistory::DidDraw() {
     draw_duration_history_.InsertSample(draw_duration);
   }
 
-  start_draw_time_ = base::TimeTicks();
+  SetCompositorDrawingContinuously(true);
+  if (!draw_end_time_prev_.is_null()) {
+    base::TimeDelta draw_interval = draw_end_time - draw_end_time_prev_;
+    uma_reporter_->AddDrawInterval(draw_interval);
+  }
+  draw_end_time_prev_ = draw_end_time;
+
+  if (begin_main_frame_committing_continuously_ && used_new_active_tree) {
+    if (!new_active_tree_draw_end_time_prev_.is_null()) {
+      base::TimeDelta draw_interval =
+          draw_end_time - new_active_tree_draw_end_time_prev_;
+      uma_reporter_->AddCommitInterval(draw_interval);
+    }
+    new_active_tree_draw_end_time_prev_ = draw_end_time;
+  }
+
+  draw_start_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::DidSwapBuffers() {