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;
 
+constexpr base::TimeDelta kSwapAckWatchdogTimeout =
+    base::TimeDelta::FromSeconds(8);
+
 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),
       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::DidCreateAndInitializeCompositorFrameSink() {
   // 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;
 }
 
 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);
   }
 
+  if (swap_ack_watchdog_enabled_) {
+    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;
+    }
+  }
+
   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;
 }
 
 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_) {
+    bool was_fast = swap_to_ack_duration < kSwapAckWatchdogTimeout;
+    uma_reporter_->AddSwapAckWasFast(was_fast);
+    swap_ack_watchdog_enabled_ = false;
+  }
   swap_start_time_ = base::TimeTicks();
 }
 
 }  // namespace cc