cc: Add MainAndImplFrameTimeDelta UMA.

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 f3ac0670525bd31d389c2008aebfd5c743649364..7f6e92563c46333ea287543a9925b085b39f573b 100644
--- a/cc/scheduler/compositor_timing_history.cc
+++ b/cc/scheduler/compositor_timing_history.cc
@@ -50,6 +50,9 @@ class CompositorTimingHistory::UMAReporter {
                                base::TimeDelta estimate,
                                bool affects_estimate) = 0;
   virtual void AddSwapToAckLatency(base::TimeDelta duration) = 0;
+
+  // Synchronization measurements
+  virtual void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) = 0;
 };
 
 namespace {
@@ -216,6 +219,11 @@ class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
     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 {
@@ -297,6 +305,11 @@ class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
     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 {
@@ -331,6 +344,7 @@ class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
                        base::TimeDelta estimate,
                        bool affects_estimate) override {}
   void AddSwapToAckLatency(base::TimeDelta duration) override {}
+  void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {}
 };
 
 }  // namespace
@@ -491,10 +505,14 @@ void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
   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);
@@ -510,11 +528,15 @@ void CompositorTimingHistory::BeginMainFrameStarted(
 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() {
@@ -651,6 +673,10 @@ void CompositorTimingHistory::DidActivate() {
     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() {
@@ -658,7 +684,9 @@ void CompositorTimingHistory::WillDraw() {
   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_;
@@ -683,13 +711,23 @@ void CompositorTimingHistory::DidDraw(bool used_new_active_tree) {
   }
   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();