Add BeginFrameLatency 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"
 #include "base/metrics/histogram_macros.h"
 #include "base/trace_event/trace_event.h"
 #include "cc/debug/rendering_stats_instrumentation.h"
 
 namespace cc {
 
 class CompositorTimingHistory::UMAReporter {
  public:
   virtual ~UMAReporter() {}
 
   // Throughput measurements
   virtual void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) = 0;
   virtual void AddBeginMainFrameIntervalNotCritical(
       base::TimeDelta interval) = 0;
   virtual void AddCommitInterval(base::TimeDelta interval) = 0;
   virtual void AddDrawInterval(base::TimeDelta interval) = 0;
 
   // Latency measurements
+  virtual void AddBeginMainFrameLatency(base::TimeDelta delta) = 0;
   virtual void AddBeginMainFrameQueueDurationCriticalDuration(
       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;
@@ skipping 151 matching lines @@
   }
 
   void AddSubmitAckWasFast(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);
   }
+
+  void AddBeginMainFrameLatency(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
+        "Scheduling.Renderer.VsyncToBeginMainFrameLatency", delta);
+  }
 };
 
 class BrowserUMAReporter : public CompositorTimingHistory::UMAReporter {
  public:
   ~BrowserUMAReporter() override {}
 
   void AddBeginMainFrameIntervalCritical(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Browser.BeginMainFrameIntervalCritical", interval);
   }
@@ skipping 57 matching lines @@
   }
 
   void AddSubmitAckWasFast(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);
   }
+
+  void AddBeginMainFrameLatency(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
+        "Scheduling.Browser.VsyncToBeginMainFrameLatency", 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 AddSubmitToAckLatency(base::TimeDelta duration) override {}
   void AddSubmitAckWasFast(bool was_fast) override {}
   void AddMainAndImplFrameTimeDelta(base::TimeDelta delta) override {}
+  void AddBeginMainFrameLatency(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),
@@ skipping 137 matching lines @@
   return draw_duration_history_.Percentile(kDrawEstimationPercentile);
 }
 
 void CompositorTimingHistory::DidCreateAndInitializeCompositorFrameSink() {
   // After we get a new output surface, we won't get a spurious
   // CompositorFrameAck from the old output surface.
   submit_start_time_ = base::TimeTicks();
   submit_ack_watchdog_enabled_ = false;
 }
 
 void CompositorTimingHistory::WillBeginImplFrame(

[brianderson, 2017/03/15 21:08:05]

You may want to track the latency of this entry point instead (or also). 

The BeginMainFrame can be throttled because of back pressure, which will make
latency look worse than it otherwise would.

BeginImplFrame always runs as soon as we get the BeginFrame message, so its
latency will better reflect OS scheduling badness.

[stanisc, 2017/03/15 21:13:45]

Thanks, I'll do an additional change to implement this suggestion. So this is
called before WillBeginMainFrame, right? Should I capture Now() here and use it
in WillBeginMainFrame to report the latency?

     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);
@@ skipping 17 matching lines @@
 }
 
 void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
   SetBeginMainFrameNeededContinuously(false);
   SetBeginMainFrameCommittingContinuously(false);
   SetCompositorDrawingContinuously(false);
 }
 
 void CompositorTimingHistory::WillBeginMainFrame(
     bool on_critical_path,
-    base::TimeTicks main_frame_time) {
+    base::TimeTicks main_frame_time,
+    BeginFrameArgs::BeginFrameArgsType frame_type) {
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_frame_time_);
 
   begin_main_frame_on_critical_path_ = on_critical_path;
   begin_main_frame_sent_time_ = Now();
   begin_main_frame_frame_time_ = main_frame_time;
 
+  if (frame_type == BeginFrameArgs::NORMAL) {
+    uma_reporter_->AddBeginMainFrameLatency(begin_main_frame_sent_time_ -
+                                            begin_main_frame_frame_time_);
+  }
+
   did_send_begin_main_frame_ = true;
   SetBeginMainFrameNeededContinuously(true);
 }
 
 void CompositorTimingHistory::BeginMainFrameStarted(
     base::TimeTicks main_thread_start_time) {
   DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);
   DCHECK_EQ(base::TimeTicks(), begin_main_frame_start_time_);
   begin_main_frame_start_time_ = main_thread_start_time;
 }
@@ skipping 211 matching lines @@
   uma_reporter_->AddSubmitToAckLatency(submit_to_ack_duration);
   if (submit_ack_watchdog_enabled_) {
     bool was_fast = submit_to_ack_duration < kSubmitAckWatchdogTimeout;
     uma_reporter_->AddSubmitAckWasFast(was_fast);
     submit_ack_watchdog_enabled_ = false;
   }
   submit_start_time_ = base::TimeTicks();
 }
 
 }  // namespace cc