cc: Add SwapAck watchdog.

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 40 matching lines @@
 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
+// 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 218 matching lines @@
   void AddActivateDuration(base::TimeDelta duration) override {}
   void AddDrawDuration(base::TimeDelta duration) override {}
   void AddSwapToAckLatency(base::TimeDelta duration) override {}
   void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {}
 };
 
 }  // namespace
 
 CompositorTimingHistory::CompositorTimingHistory(
     bool using_synchronous_renderer_compositor,
+    bool enable_swap_ack_watchdog,
     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_(enable_swap_ack_watchdog),
+      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_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.
+  // If it is, crash to get diagnostic information.
+  // Otherwise, check again in M BeginImplFrames.
+  if (swap_ack_watchdog_enabled_ && !swap_start_time_.is_null()) {
+    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_;
+      CHECK_LT(swap_not_acked_time_, kSwapAckWatchdogTimeout);
+      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_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);
   swap_start_time_ = base::TimeTicks();
 }
 
 }  // namespace cc