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 100 matching lines @@
   void AddCommitInterval(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Renderer.CommitInterval", interval);
   }
 
   void AddDrawInterval(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED("Scheduling.Renderer.DrawInterval",
                                              interval);
   }
 
+  void AddBeginImplFrameLatency(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
+        "Scheduling.Renderer.VsyncToBeginImplFrameLatency", delta);

[brianderson, 2017/03/16 20:53:16]

Using the "Vsync" is true on Windows, but is not quite right on Android. Maybe
just call it BeginImplFrameLatency?

[stanisc, 2017/03/16 21:01:12]

ajuma@ suggested adding VSync in the previous review but I am OK with taking it
off. I'll change it before submitting.

isherman@, this will require histograms.xml to be changed again to reflect the
new name.

[Ilya Sherman, 2017/03/16 21:28:04]

Either name is ok with me.  Thanks.

[stanisc, 2017/03/16 23:17:41]

Done.

+  }
+
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
         "Scheduling.Renderer.BeginMainFrameQueueDurationCritical", duration);
   }
 
   void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
         "Scheduling.Renderer.BeginMainFrameQueueDurationNotCritical", duration);
@@ skipping 31 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);
   }
 
   void AddBeginMainFrameIntervalNotCritical(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Browser.BeginMainFrameIntervalNotCritical", interval);
   }
 
   void AddCommitInterval(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED(
         "Scheduling.Browser.CommitInterval", interval);
   }
 
   void AddDrawInterval(base::TimeDelta interval) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_VSYNC_ALIGNED("Scheduling.Browser.DrawInterval",
                                              interval);
   }
 
+  void AddBeginImplFrameLatency(base::TimeDelta delta) override {
+    UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
+        "Scheduling.Browser.VsyncToBeginImplFrameLatency", delta);
+  }
+
   void AddBeginMainFrameQueueDurationCriticalDuration(
       base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
         "Scheduling.Browser.BeginMainFrameQueueDurationCritical", duration);
   }
 
   void AddBeginMainFrameQueueDurationNotCriticalDuration(
       base::TimeDelta duration) override {
     UMA_HISTOGRAM_CUSTOM_TIMES_DURATION(
         "Scheduling.Browser.BeginMainFrameQueueDurationNotCritical", duration);
@@ skipping 31 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 AddBeginImplFrameLatency(base::TimeDelta delta) 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 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,
+    base::TimeTicks now) {
   // 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 (submit_ack_watchdog_enabled_) {
-    base::TimeDelta submit_not_acked_time_ = Now() - submit_start_time_;
+    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.
       submit_ack_watchdog_enabled_ = false;
     }
   }
 
+  if (frame_type == BeginFrameArgs::NORMAL)
+    uma_reporter_->AddBeginImplFrameLatency(now - frame_time);
+
   did_send_begin_main_frame_ = false;
 }
 
 void CompositorTimingHistory::WillFinishImplFrame(bool needs_redraw) {
   if (!needs_redraw)
     SetCompositorDrawingContinuously(false);
 }
 
 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