cc: Add MainAndImplFrameTimeDelta UMA.

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 <stddef.h>
 #include <stdint.h>
 
 #include "base/metrics/histogram.h"
@@ skipping 32 matching lines @@
   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;
   virtual void AddSwapToAckLatency(base::TimeDelta duration) = 0;
+
+  // Synchronization measurements
+  virtual void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) = 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;
@@ skipping 147 matching lines @@
                        base::TimeDelta estimate,
                        bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Renderer", "Draw");
     DeprecatedDrawDurationUMA(duration, estimate);
   }
 
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Renderer.SwapToAckLatency",
                                       duration);
   }
+
+  void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Renderer.MainAndImplFrameTimeDelta", delta);
+  }
 };
 
 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~BrowserUMAReporter() override {}
 
   void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
         "Scheduling.Browser.BeginMainFrameIntervalCritical", interval);
   }
@@ skipping 61 matching lines @@
                        base::TimeDelta estimate,
                        bool affects_estimate) override {
     REPORT_COMPOSITOR_TIMING_HISTORY_UMA("Browser", "Draw");
     DeprecatedDrawDurationUMA(duration, estimate);
   }
 
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_MICROS("Scheduling.Browser.SwapToAckLatency",
                                       duration);
   }
+
+  void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(
+        "Scheduling.Browser.MainAndImplFrameTimeDelta", delta);
+  }
 };
 
 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 {}
@@ skipping 14 matching lines @@
   void AddPrepareTilesDuration(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 {}
   void AddSwapToAckLatency(base::TimeDelta duration) override {}
+  void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {}
 };
 
 }  // namespace
 
 CompositorTimingHistory::CompositorTimingHistory(
+    bool using_synchronous_renderer_compositor,
     UMACategory uma_category,
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
-    : enabled_(false),
+    : using_synchronous_renderer_compositor_(
+          using_synchronous_renderer_compositor),
+      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_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),
@@ skipping 118 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::DidCreateAndInitializeOutputSurface() {
+  // After we get a new output surface, we won't get a spurious
+  // swap ack from the old output surface.
+  swap_start_time_ = base::TimeTicks();
+}
+
 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) {
+void CompositorTimingHistory::WillBeginMainFrame(
+    bool on_critical_path,
+    base::TimeTicks main_frame_time) {
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
+  DCHECK_EQ(base::TimeTicks(), begin_main_frame_frame_time_);
+
   begin_main_frame_on_critical_path_ = on_critical_path;
   begin_main_frame_sent_time_ = Now();
+  begin_main_frame_frame_time_ = main_frame_time;
 
   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() {
   SetBeginMainFrameCommittingContinuously(false);
   DidBeginMainFrame();
+  begin_main_frame_frame_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::DidCommit() {
+  DCHECK_EQ(base::TimeTicks(), pending_tree_main_frame_time_);
   SetBeginMainFrameCommittingContinuously(true);
   DidBeginMainFrame();
+  pending_tree_main_frame_time_ = begin_main_frame_frame_time_;
+  begin_main_frame_frame_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::DidBeginMainFrame() {
   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
 
   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.
@@ skipping 117 matching lines @@
 
 void CompositorTimingHistory::DidActivate() {
   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);
 
+  // The synchronous compositor doesn't necessarily draw every new active tree.
+  if (!using_synchronous_renderer_compositor_)
+    DCHECK_EQ(base::TimeTicks(), active_tree_main_frame_time_);
+  active_tree_main_frame_time_ = pending_tree_main_frame_time_;
+
   activate_start_time_ = base::TimeTicks();
+  pending_tree_main_frame_time_ = base::TimeTicks();
 }
 
 void CompositorTimingHistory::WillDraw() {
   DCHECK_EQ(base::TimeTicks(), draw_start_time_);
   draw_start_time_ = Now();
 }
 
-void CompositorTimingHistory::DidDraw(bool used_new_active_tree) {
+void CompositorTimingHistory::DrawAborted() {
+  active_tree_main_frame_time_ = base::TimeTicks();
+}
+
+void CompositorTimingHistory::DidDraw(bool used_new_active_tree,
+                                      bool main_thread_missed_last_deadline,
+                                      base::TimeTicks impl_frame_time) {
   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);
   }
 
   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);
+  if (used_new_active_tree) {
+    DCHECK_NE(base::TimeTicks(), active_tree_main_frame_time_);
+    base::TimeDelta main_and_impl_delta =
+        impl_frame_time - active_tree_main_frame_time_;
+    DCHECK_GE(main_and_impl_delta, base::TimeDelta());
+    if (!using_synchronous_renderer_compositor_) {
+      DCHECK_EQ(main_thread_missed_last_deadline,
+                !main_and_impl_delta.is_zero());
     }
-    new_active_tree_draw_end_time_prev_ = draw_end_time;
+    uma_reporter_->AddMainAndImplFrameTimeDelta(main_and_impl_delta);
+    active_tree_main_frame_time_ = base::TimeTicks();
+
+    if (begin_main_frame_committing_continuously_) {
+      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