cc: Track BeginMainFrame more precisely in CompositorTimingHistory.

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() {}
 
   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(
+      base::TimeDelta duration,
+      bool affects_estimate) = 0;
   virtual void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
                                                   base::TimeDelta estimate,
                                                   bool affects_estimate) = 0;
   virtual void AddPrepareTilesDuration(base::TimeDelta duration,
                                        base::TimeDelta estimate,
                                        bool affects_estimate) = 0;
   virtual void AddActivateDuration(base::TimeDelta duration,
                                    base::TimeDelta estimate,
                                    bool affects_estimate) = 0;
   virtual void AddDrawDuration(base::TimeDelta duration,
                                base::TimeDelta estimate,
                                bool affects_estimate) = 0;
 };
 
 namespace {
 
 // Using the 90th percentile will disable latency recovery
 // if we are missing the deadline approximately ~6 times per
 // second.
 // TODO(brianderson): Fine tune the percentiles below.
 const size_t kDurationHistorySize = 60;
 const double kBeginMainFrameToCommitEstimationPercentile = 90.0;
+const double kBeginMainFrameQueueDurationCriticalEstimationPercentile = 90.0;
+const double kBeginMainFrameQueueDurationNotCriticalEstimationPercentile = 90.0;
+const double kBeginMainFrameStartToCommitEstimationPercentile = 90.0;
 const double kCommitToReadyToActivateEstimationPercentile = 90.0;
 const double kPrepareTilesEstimationPercentile = 90.0;
 const double kActivateEstimationPercentile = 90.0;
 const double kDrawEstimationPercentile = 90.0;
 
 const int kUmaDurationMinMicros = 1;
 const int64 kUmaDurationMaxMicros = 1 * base::Time::kMicrosecondsPerSecond;
 const size_t kUmaDurationBucketCount = 100;
 
 // Deprecated because they combine Browser and Renderer stats and have low
@@ skipping 18 matching lines @@
                              duration_overestimate,
                              base::TimeDelta::FromMilliseconds(1),
                              base::TimeDelta::FromMilliseconds(100), 50);
 }
 
 #define UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(name, sample)                     \
   UMA_HISTOGRAM_CUSTOM_COUNTS(name, sample.InMicroseconds(),                \
                               kUmaDurationMinMicros, kUmaDurationMaxMicros, \
                               kUmaDurationBucketCount);
 
+// Records over/under estimates.
 #define REPORT_COMPOSITOR_TIMING_HISTORY_UMA(category, subcategory)            \
   do {                                                                         \
     base::TimeDelta duration_overestimate;                                     \
     base::TimeDelta duration_underestimate;                                    \
     if (duration > estimate)                                                   \
       duration_underestimate = duration - estimate;                            \
     else                                                                       \
       duration_overestimate = estimate - duration;                             \
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(                                         \
         "Scheduling." category "." subcategory "Duration", duration);          \
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory   \
                                       "Duration.Underestimate",                \
                                       duration_underestimate);                 \
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory   \
                                       "Duration.Overestimate",                 \
                                       duration_overestimate);                  \
     if (!affects_estimate) {                                                   \
       UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory \
                                         "Duration.NotUsedForEstimate",         \
                                         duration);                             \
     }                                                                          \
   } while (false)
 
+// Does not record over/under estimates.
+#define REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(category, subcategory)           \
+  do {                                                                         \
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory,  \
+                                      duration);                               \
+    if (!affects_estimate) {                                                   \
+      UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling." category "." subcategory \
+                                        ".NotUsedForEstimate",                 \
+                                        duration);                             \
+    }                                                                          \
+  } while (false)
+
 class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~RendererUMAReporter() override {}
 
   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(
+        "Renderer", "BeginMainFrameQueueDurationCritical");
+  }
+
+  void AddBeginMainFrameQueueDurationNotCriticalDuration(
+      base::TimeDelta duration,
+      bool affects_estimate) override {
+    REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(
+        "Renderer", "BeginMainFrameQueueDurationNotCritical");
+  }
+
+  void AddBeginMainFrameStartToCommitDuration(base::TimeDelta duration,
+                                              bool affects_estimate) override {
+    REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(
+        "Renderer", "BeginMainFrameStartToCommitDuration");
+  }
+
   void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
                                           base::TimeDelta estimate,
                                           bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "CommitToReadyToActivate");
   }
 
   void AddPrepareTilesDuration(base::TimeDelta duration,
                                base::TimeDelta estimate,
                                bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "PrepareTiles");
@@ skipping 16 matching lines @@
 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~BrowserUMAReporter() override {}
 
   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(
+        "Browser", "BeginMainFrameQueueDurationCritical");
+  }
+
+  void AddBeginMainFrameQueueDurationNotCriticalDuration(
+      base::TimeDelta duration,
+      bool affects_estimate) override {
+    REPORT_COMPOSITOR_TIMING_HISTORY_UMA2(
+        "Browser", "BeginMainFrameQueueDurationNotCritical");
+  }
+
+  void AddBeginMainFrameStartToCommitDuration(base::TimeDelta duration,
+                                              bool affects_estimate) override {
+    REPORT_COMPOSITOR_TIMING_HISTORY_UMA2("Browser",
+                                          "BeginMainFrameStartToCommit");
+  }
+
   void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
                                           base::TimeDelta estimate,
                                           bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "CommitToReadyToActivate");
   }
 
   void AddPrepareTilesDuration(base::TimeDelta duration,
                                base::TimeDelta estimate,
                                bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "PrepareTiles");
   }
 
   void AddActivateDuration(base::TimeDelta duration,
                            base::TimeDelta estimate,
                            bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "Activate");
   }
 
   void AddDrawDuration(base::TimeDelta duration,
                        base::TimeDelta estimate,
                        bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "Draw");
     DeprecatedDrawDurationUMA(duration, estimate);
   }
 };
 
 class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~NullUMAReporter() 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,
+                                              bool affects_estimate) override {}
+  void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
+                                          base::TimeDelta estimate,
+                                          bool affects_estimate) override {}
   void AddPrepareTilesDuration(base::TimeDelta duration,
                                base::TimeDelta estimate,
                                bool affects_estimate) override {}
-  void AddBeginMainFrameToCommitDuration(base::TimeDelta duration,
-                                         base::TimeDelta estimate,
-                                         bool affects_estimate) override {}
-  void AddCommitToReadyToActivateDuration(base::TimeDelta duration,
-                                          base::TimeDelta estimate,
-                                          bool affects_estimate) override {}
   void AddActivateDuration(base::TimeDelta duration,
                            base::TimeDelta estimate,
                            bool affects_estimate) override {}
   void AddDrawDuration(base::TimeDelta duration,
                        base::TimeDelta estimate,
                        bool affects_estimate) override {}
 };
 
 }  // namespace
 
 CompositorTimingHistory::CompositorTimingHistory(
     UMACategory uma_category,
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
     : enabled_(false),
-      begin_main_frame_to_commit_duration_history_(kDurationHistorySize),
+      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),
       uma_reporter_(CreateUMAReporter(uma_category)),
       rendering_stats_instrumentation_(rendering_stats_instrumentation) {}
 
 CompositorTimingHistory::~CompositorTimingHistory() {
 }
 
 scoped_ptr<CompositorTimingHistory::UMAReporter>
 CompositorTimingHistory::CreateUMAReporter(UMACategory category) {
   switch (category) {
     case RENDERER_UMA:
@@ skipping 27 matching lines @@
 base::TimeTicks CompositorTimingHistory::Now() const {
   return base::TimeTicks::Now();
 }
 
 void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
   enabled_ = enabled;
 }
 
 base::TimeDelta
 CompositorTimingHistory::BeginMainFrameToCommitDurationEstimate() const {
-  return begin_main_frame_to_commit_duration_history_.Percentile(
+  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);
+}
+
+base::TimeDelta
+CompositorTimingHistory::BeginMainFrameQueueDurationNotCriticalEstimate()
+    const {
+  return begin_main_frame_queue_duration_not_critical_history_.Percentile(
+      kBeginMainFrameQueueDurationNotCriticalEstimationPercentile);
+}
+
+base::TimeDelta
+CompositorTimingHistory::BeginMainFrameStartToCommitDurationEstimate() const {
+  return begin_main_frame_start_to_commit_duration_history_.Percentile(
+      kBeginMainFrameStartToCommitEstimationPercentile);
+}
+
+base::TimeDelta
 CompositorTimingHistory::CommitToReadyToActivateDurationEstimate() const {
   return commit_to_ready_to_activate_duration_history_.Percentile(
       kCommitToReadyToActivateEstimationPercentile);
 }
 
 base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
   return prepare_tiles_duration_history_.Percentile(
       kPrepareTilesEstimationPercentile);
 }
 
 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() {
+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();
 }
 
+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();
 }
 
 void CompositorTimingHistory::DidCommit() {
   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 
   commit_time_ = Now();
 
-  base::TimeDelta begin_main_frame_to_commit_duration =
+  // 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_;
+  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_;
 
   // 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_to_commit_estimate =
+  base::TimeDelta begin_main_frame_sent_to_commit_estimate =
       BeginMainFrameToCommitDurationEstimate();
   uma_reporter_->AddBeginMainFrameToCommitDuration(
-      begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate,
-      enabled_);
+      begin_main_frame_sent_to_commit_duration,
+      begin_main_frame_sent_to_commit_estimate, enabled_);
   rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
-      begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate);
+      begin_main_frame_sent_to_commit_duration,
+      begin_main_frame_sent_to_commit_estimate);
+
+  if (begin_main_frame_start_time_is_valid) {
+    if (begin_main_frame_on_critical_path_) {
+      uma_reporter_->AddBeginMainFrameQueueDurationCriticalDuration(
+          begin_main_frame_queue_duration, enabled_);
+    } else {
+      uma_reporter_->AddBeginMainFrameQueueDurationNotCriticalDuration(
+          begin_main_frame_queue_duration, enabled_);
+    }
+  }
+
+  uma_reporter_->AddBeginMainFrameStartToCommitDuration(
+      begin_main_frame_start_to_commit_duration, enabled_);
 
   if (enabled_) {
-    begin_main_frame_to_commit_duration_history_.InsertSample(
-        begin_main_frame_to_commit_duration);
+    begin_main_frame_sent_to_commit_duration_history_.InsertSample(
+        begin_main_frame_sent_to_commit_duration);
+    if (begin_main_frame_on_critical_path_) {
+      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);
   }
 
   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();
 }
 
 void CompositorTimingHistory::DidPrepareTiles() {
   DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
 
@@ skipping 69 matching lines @@
   uma_reporter_->AddDrawDuration(draw_duration, draw_estimate, enabled_);
 
   if (enabled_) {
     draw_duration_history_.InsertSample(draw_duration);
   }
 
   start_draw_time_ = base::TimeTicks();
 }
 
 }  // namespace cc