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
+// unnecessary idle wakeups.

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

I don't understand the point about idle wakeups. And I'm not sure the
optimization to avoid calling Now is needed given that we would only call it
once per frame.

I think an important goal is to avoid excessive UMA reporting. So should we even
report when swap ack is fast?

I think we should only report once if swap ack is late, then reset the "swap ack
is late" state only when we get the next swap ack. That would be once per
user-perceived renderer freeze. WDYT?

[Ilya Sherman, 2016/08/30 20:56:25]

In general, it's better to build in a baseline for a metric than not to -- the
baseline gives context to the number that you are primarily focused on. 
Incrementing a bucket in an UMA histogram is intentionally *very* cheap, so it
shouldn't be terribly expensive to report fast swap acks.

From the metric team's perspective, reducing the number of histograms that we
report to UMA is generally speaking quite useful.  Reducing the number of
buckets in an UMA histogram by one is generally not very impactful.

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

Regarding idle wakeups: I was referring to posting an 8s delayed task after
every swap, but wasn't clear. I'll just avoid the reference.

+// 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);

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

nit: seems to be extra indentation here

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