cc: CompositorTimingHistory throughput UMAs

cc/scheduler/compositor_timing_history.cc

 // 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 "base/trace_event/trace_event.h"
 #include "cc/debug/rendering_stats_instrumentation.h"
 
 namespace cc {
 
 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;
   virtual void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) = 0;
   virtual void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) = 0;
   virtual void AddBeginMainFrameStartToCommitDuration(
@@ skipping 96 matching lines @@
       UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory \
                                         ".NotUsedForEstimate",                 \
                                         duration);                             \
     }                                                                          \
   } while (false)
 
 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 {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "BeginMainFrameToCommit");
   }
 
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(
@@ skipping 41 matching lines @@
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Renderer.SwapToAckLatency",
                                       duration);
   }
 };
 
 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 {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "BeginMainFrameToCommit");
   }
 
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(
@@ skipping 40 matching lines @@
 
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Browser.SwapToAckLatency",
                                       duration);
   }
 };
 
 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 {}
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) override {}
   void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration,
       bool affects_estimate) override {}
   void AddBeginMainFrameStartToCommitDuration(base::TimeDelta duration,
@@ skipping 12 matching lines @@
                        bool affects_estimate) override {}
   void AddSwapToAckLatency(base::TimeDelta duration) override {}
 };
 
 }  // namespace
 
 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_(
           kDurationHistorySize),
       begin_main_frame_start_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),
       begin_main_frame_on_critical_path_(false),
@@ skipping 35 matching lines @@
 }
 
 base::TimeTicks CompositorTimingHistory::Now() const {
   return base::TimeTicks::Now();
 }
 
 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(
       kBeginMainFrameToCommitEstimationPercentile);
 }
 
 base::TimeDelta
 CompositorTimingHistory::BeginMainFrameQueueDurationCriticalEstimate() const {
   return begin_main_frame_queue_duration_critical_history_.Percentile(
       kBeginMainFrameQueueDurationCriticalEstimationPercentile);
@@ skipping 24 matching lines @@
 }
 
 base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
   return activate_duration_history_.Percentile(kActivateEstimationPercentile);
 }
 
 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(
     base::TimeTicks main_thread_start_time) {
   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_start_time_);
   begin_main_frame_start_time_ = main_thread_start_time;
 }
 
 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
   // the results.
   bool begin_main_frame_start_time_is_valid =
       !begin_main_frame_start_time_.is_null();
   if (!begin_main_frame_start_time_is_valid)
     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
   // of our predictions.
   base::TimeDelta begin_main_frame_sent_to_commit_estimate =
       BeginMainFrameToCommitDurationEstimate();
   uma_reporter_->AddBeginMainFrameToCommitDuration(
       begin_main_frame_sent_to_commit_duration,
       begin_main_frame_sent_to_commit_estimate, enabled_);
   rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
@@ skipping 20 matching lines @@
       begin_main_frame_queue_duration_critical_history_.InsertSample(
           begin_main_frame_queue_duration);
     } else {
       begin_main_frame_queue_duration_not_critical_history_.InsertSample(
           begin_main_frame_queue_duration);
     }
     begin_main_frame_start_to_commit_duration_history_.InsertSample(
         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
   // of our predictions.
 
   base::TimeDelta commit_to_ready_to_activate_estimate =
       CommitToReadyToActivateDurationEstimate();
   uma_reporter_->AddCommitToReadyToActivateDuration(
       time_since_commit, commit_to_ready_to_activate_estimate, enabled_);
   rendering_stats_instrumentation_->AddCommitToActivateDuration(
       time_since_commit, commit_to_ready_to_activate_estimate);
 
   if (enabled_) {
     commit_to_ready_to_activate_duration_history_.InsertSample(
         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
   // of our predictions.
   base::TimeDelta draw_estimate = DrawDurationEstimate();
   rendering_stats_instrumentation_->AddDrawDuration(draw_duration,
                                                     draw_estimate);
 
   uma_reporter_->AddDrawDuration(draw_duration, draw_estimate, enabled_);
 
   if (enabled_) {
     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() {
   DCHECK_EQ(base::TimeTicks(), swap_start_time_);
   swap_start_time_ = Now();
 }
 
 void CompositorTimingHistory::DidSwapBuffersComplete() {
   DCHECK_NE(base::TimeTicks(), swap_start_time_);
   base::TimeDelta swap_to_ack_duration = Now() - swap_start_time_;
   uma_reporter_->AddSwapToAckLatency(swap_to_ack_duration);
   swap_start_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::DidSwapBuffersReset() {
   swap_start_time_ = base::TimeTicks();
 }
 
 }  // namespace cc