cc: Add a Scheduling.SwapAckWasFast 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 8b474c09b3d20a070095c45f3c6cb3caf722bedd..574046710a5b7ffe50c614ad6de08c1e04be0d12 100644
--- a/cc/scheduler/compositor_timing_history.cc
+++ b/cc/scheduler/compositor_timing_history.cc
@@ -37,6 +37,7 @@ class CompositorTimingHistory::UMAReporter {
   virtual void AddActivateDuration(base::TimeDelta duration) = 0;
   virtual void AddDrawDuration(base::TimeDelta duration) = 0;
   virtual void AddSwapToAckLatency(base::TimeDelta duration) = 0;
+  virtual void AddSwapAckWasFast(bool was_fast) = 0;
 
   // Synchronization measurements
   virtual void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) = 0;
@@ -58,6 +59,16 @@ const double kPrepareTilesEstimationPercentile = 90.0;
 const double kActivateEstimationPercentile = 90.0;
 const double kDrawEstimationPercentile = 90.0;
 
+// The watchdog uses a combination of BeginImplFrame counts and
+// actual timestamps to avoid calling Now() too often or adding

[sunnyps, 2016/08/30 18:31:04]

Is this optimization really needed? Even without the optimization wouldn't Now()
only be called once per frame?

[brianderson, 2016/08/30 22:30:32]

A few years ago, we were especially concerned about buggy AMD cpu's that needed
special (slow) workarounds to ensure the performance timer is monotonic on
Windows. Revisiting the code in time_win.cc, it looks like we just avoid using
it now on that cpu, so I'll remove the optimization.

+// unnecessary idle wakeups.
+// This will break if we aren't receiving BeginFrames, but this
+// is primarily for crbug.com/602486, where we are receiving them.
+const int kSwapAckWatchdogBeginImplFrameCount = 8 * 61;
+const int kSwapAckWatchdogBeginImplFrameReCount = 60;
+const base::TimeDelta kSwapAckWatchdogTimeout =
+    base::TimeDelta::FromMicroseconds(8000000);
+
 const int kUmaDurationMinMicros = 1;
 const int64_t kUmaDurationMaxMicros = base::Time::kMicrosecondsPerSecond / 5;
 const int kUmaDurationBucketCount = 100;
@@ -191,6 +202,10 @@ class RendererUMAReporter : public CompositorTimingHistory::UMAReporter {
                                         duration);
   }
 
+  void AddSwapAckWasFast(bool was_fast) override {
+    UMA_HISTOGRAM_BOOLEAN("Scheduling.Renderer.SwapAckWasFast", was_fast);
+  }
+
   void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Renderer.MainAndImplFrameTimeDelta", delta);
@@ -264,6 +279,10 @@ class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
                                         duration);
   }
 
+  void AddSwapAckWasFast(bool was_fast) override {
+      UMA_HISTOGRAM_BOOLEAN("Scheduling.Browser.SwapAckWasFast", was_fast);
+  }
+
   void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Browser.MainAndImplFrameTimeDelta", delta);
@@ -289,6 +308,7 @@ class NullUMAReporter : public CompositorTimingHistory::UMAReporter {
   void AddActivateDuration(base::TimeDelta duration) override {}
   void AddDrawDuration(base::TimeDelta duration) override {}
   void AddSwapToAckLatency(base::TimeDelta duration) override {}
+  void AddSwapAckWasFast(bool was_fast) override {}
   void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {}
 };
 
@@ -315,6 +335,8 @@ CompositorTimingHistory::CompositorTimingHistory(
       activate_duration_history_(kDurationHistorySize),
       draw_duration_history_(kDurationHistorySize),
       begin_main_frame_on_critical_path_(false),
+      swap_ack_watchdog_enabled_(false),
+      swap_ack_watchdog_begin_impl_frame_count_(0),
       uma_reporter_(CreateUMAReporter(uma_category)),
       rendering_stats_instrumentation_(rendering_stats_instrumentation) {}
 
@@ -443,6 +465,8 @@ 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();
+  swap_ack_watchdog_enabled_ = false;
+  swap_ack_watchdog_begin_impl_frame_count_ = 0;
 }
 
 void CompositorTimingHistory::WillBeginImplFrame(
@@ -458,6 +482,24 @@ void CompositorTimingHistory::WillBeginImplFrame(
     SetBeginMainFrameCommittingContinuously(false);
   }
 
+  // After N BeginImplFrames, check if the swap ack is taking too long.
+  // Otherwise, check again in M BeginImplFrames.
+  if (swap_ack_watchdog_enabled_) {
+    swap_ack_watchdog_begin_impl_frame_count_++;
+    if (swap_ack_watchdog_begin_impl_frame_count_ ==
+        kSwapAckWatchdogBeginImplFrameCount) {
+      base::TimeDelta swap_not_acked_time_ = Now() - swap_start_time_;
+      if (swap_not_acked_time_ > kSwapAckWatchdogTimeout) {
+        uma_reporter_->AddSwapAckWasFast(false);
+        // Only record this UMA once per swap.
+        swap_ack_watchdog_enabled_ = false;
+      } else {
+        swap_ack_watchdog_begin_impl_frame_count_ -=
+            kSwapAckWatchdogBeginImplFrameReCount;
+      }
+    }
+  }
+
   did_send_begin_main_frame_ = false;
 }
 
@@ -697,12 +739,18 @@ void CompositorTimingHistory::DidDraw(bool used_new_active_tree,
 void CompositorTimingHistory::DidSwapBuffers() {
   DCHECK_EQ(base::TimeTicks(), swap_start_time_);
   swap_start_time_ = Now();
+  swap_ack_watchdog_enabled_ = true;
+  swap_ack_watchdog_begin_impl_frame_count_ = 0;
 }
 
 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);
+  if (swap_ack_watchdog_enabled_) {
+    uma_reporter_->AddSwapAckWasFast(true);
+    swap_ack_watchdog_enabled_ = false;
+  }
   swap_start_time_ = base::TimeTicks();
 }