cc: Add a Scheduling.SwapAckWasFast 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/memory/ptr_util.h"
@@ skipping 19 matching lines @@
       base::TimeDelta duration) = 0;
   virtual void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration) = 0;
   virtual void AddBeginMainFrameStartToCommitDuration(
       base::TimeDelta duration) = 0;
   virtual void AddCommitToReadyToActivateDuration(base::TimeDelta duration) = 0;
   virtual void AddPrepareTilesDuration(base::TimeDelta duration) = 0;
   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;
 };
 
 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 kBeginMainFrameQueueDurationEstimationPercentile = 90.0;
 const double kBeginMainFrameQueueDurationCriticalEstimationPercentile = 90.0;
 const double kBeginMainFrameQueueDurationNotCriticalEstimationPercentile = 90.0;
 const double kBeginMainFrameStartToCommitEstimationPercentile = 90.0;
 const double kCommitToReadyToActivateEstimationPercentile = 90.0;
 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;
 
 // This macro is deprecated since its bucket count uses too much bandwidth.
 // It also has sub-optimal range and bucket distribution.
 // TODO(brianderson): Delete this macro and associated UMAs once there is
 // sufficient overlap with the re-bucketed UMAs.
 #define UMA_HISTOGRAM_CUSTOM_TIMES_MICROS(name, sample)                     \
   UMA_HISTOGRAM_CUSTOM_COUNTS(name, sample.InMicroseconds(),                \
@@ skipping 113 matching lines @@
   void AddDrawDuration(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Renderer.DrawDuration",
                                         duration);
   }
 
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Renderer.SwapToAckLatency",
                                         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);
   }
 };
 
 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~BrowserUMAReporter() override {}
 
@@ skipping 53 matching lines @@
   void AddDrawDuration(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Browser.DrawDuration",
                                         duration);
   }
 
   void AddSwapToAckLatency(base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION("Scheduling.Browser.SwapToAckLatency",
                                         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);
   }
 };
 
 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 {}
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration) override {}
   void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration) override {}
   void AddBeginMainFrameStartToCommitDuration(
       base::TimeDelta duration) override {}
   void AddCommitToReadyToActivateDuration(base::TimeDelta duration) override {}
   void AddPrepareTilesDuration(base::TimeDelta duration) override {}
   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 {}
 };
 
 }  // namespace
 
 CompositorTimingHistory::CompositorTimingHistory(
     bool using_synchronous_renderer_compositor,
     UMACategory uma_category,
     RenderingStatsInstrumentation* rendering_stats_instrumentation)
     : 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_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),
       commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
       prepare_tiles_duration_history_(kDurationHistorySize),
       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) {}
 
 CompositorTimingHistory::~CompositorTimingHistory() {
 }
 
 std::unique_ptr<CompositorTimingHistory::UMAReporter>
 CompositorTimingHistory::CreateUMAReporter(UMACategory category) {
   switch (category) {
     case RENDERER_UMA:
@@ skipping 108 matching lines @@
 }
 
 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();
+  swap_ack_watchdog_enabled_ = false;
+  swap_ack_watchdog_begin_impl_frame_count_ = 0;
 }
 
 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);
   }
 
+  // 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;
 }
 
 void CompositorTimingHistory::WillFinishImplFrame(bool needs_redraw) {
   if (!needs_redraw)
     SetCompositorDrawingContinuously(false);
 }
 
 void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
   SetBeginMainFrameNeededContinuously(false);
@@ skipping 219 matching lines @@
       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();
+  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();
 }
 
 }  // namespace cc