Reimplement vsync latency UMA to be based on BeginImplFrame rather than BeginMainFrame

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 AddBeginImplFrameLatency(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 152 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 {
+  void AddBeginImplFrameLatency(base::TimeDelta delta) override {

[brianderson, 2017/03/16 19:11:56]

Nit: Here and below, can you put the method in the same order as the UMARporter
base class?

[stanisc, 2017/03/16 20:45:48]

Done.

     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
-        "Scheduling.Renderer.VsyncToBeginMainFrameLatency", delta);
+        "Scheduling.Renderer.VsyncToBeginImplFrameLatency", 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 59 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 {
+  void AddBeginImplFrameLatency(base::TimeDelta delta) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
-        "Scheduling.Browser.VsyncToBeginMainFrameLatency", delta);
+        "Scheduling.Browser.VsyncToBeginImplFrameLatency", 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 {}
+  void AddBeginImplFrameLatency(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 138 matching lines @@
 }
 
 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(
-    bool new_active_tree_is_likely) {
+    bool new_active_tree_is_likely,
+    base::TimeTicks frame_time,
+    BeginFrameArgs::BeginFrameArgsType frame_type) {
   // 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 (frame_type == BeginFrameArgs::NORMAL)
+    uma_reporter_->AddBeginImplFrameLatency(Now() - frame_time);
+
   if (!new_active_tree_is_likely && !did_send_begin_main_frame_) {
     SetBeginMainFrameNeededContinuously(false);
     SetBeginMainFrameCommittingContinuously(false);
   }
 
   if (submit_ack_watchdog_enabled_) {
     base::TimeDelta submit_not_acked_time_ = Now() - submit_start_time_;
     if (submit_not_acked_time_ >= kSubmitAckWatchdogTimeout) {
       uma_reporter_->AddSubmitAckWasFast(false);
       // Only record this UMA once per submitted CompositorFrame.
@@ skipping 10 matching lines @@
 }
 
 void CompositorTimingHistory::BeginImplFrameNotExpectedSoon() {
   SetBeginMainFrameNeededContinuously(false);
   SetBeginMainFrameCommittingContinuously(false);
   SetCompositorDrawingContinuously(false);
 }
 
 void CompositorTimingHistory::WillBeginMainFrame(
     bool on_critical_path,
-    base::TimeTicks main_frame_time,
-    BeginFrameArgs::BeginFrameArgsType frame_type) {
+    base::TimeTicks main_frame_time) {
   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