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 146 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(
     UMACategory uma_category,
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
     : enabled_(false),
       did_send_begin_main_frame_(false),
       begin_main_frame_needed_continuously_(false),
@@ skipping 140 matching lines @@
   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 116 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);
 
   activate_start_time_ = base::TimeTicks();
+
+  DCHECK_EQ(base::TimeTicks(), active_tree_main_frame_time_);
+  active_tree_main_frame_time_ = pending_tree_main_frame_time_;
+  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::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());
+    DCHECK_EQ(main_thread_missed_last_deadline, !main_and_impl_delta.is_zero());

[brianderson, 2016/02/11 01:43:45]

Good thing we tried recording the delta. I added this DCHECK to sanity check the
delta approach v.s the bool approach and I noticed a discrepancy where it was
triggering every once and a while.

Turns out main_thread_missed_last_deadline stays true after aborting a
BeginMainFrame, which causes:
1) The scheduler to needlessly skip the next BeginMainFrame in some cases.
2) This DCHECK to trigger if the next BeginMainFrame isn't aborted (because of
impl latency takes priority or long estimates).

I fixed that bug and added a unit test as part of this patch, but can split it
out.

Also: still need to fix some other issues with the WebView, since it breaks some
assumptions in CompositorTimeingHistory.

+    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;
     }
-    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