presentation time: Measure the delta from swap time.

Report the delta between the swap-time in the renderer, and the
presentation time in the gpu. This would allow us to understand
how switching to presentation-time would affect the paint-timing
metrics.

BUG=899847

Change-Id: I31dd6f5f9ef159e464d7616d2ad04a9c971d7d4a
Reviewed-on: https://chromium-review.googlesource.com/c/1305249Reviewed-by: Bryan McQuade <bmcquade@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Reviewed-by: Antoine Labour <piman@chromium.org>
Reviewed-by: Timothy Dresser <tdresser@chromium.org>
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#606288}

components/viz/service/display/display.cc

@@ -528,6 +528,7 @@ void Display::DidReceivePresentationFeedback(
     const gfx::PresentationFeedback& feedback) {
   DCHECK(!pending_presented_callbacks_.empty());
   auto& callbacks = pending_presented_callbacks_.front().second;
+  auto copy_feedback = feedback;
 #if defined(OS_ANDROID)
   // Temporary to investigate large presentation times.
   // https://crbug.com/894440
@@ -545,6 +546,9 @@ void Display::DidReceivePresentationFeedback(
       base::debug::DumpWithoutCrashing();
       // In debug builds, just crash immediately.
       DCHECK(false);
+
+      // Invalidate the feedback.
+      copy_feedback = gfx::PresentationFeedback::Failure();
     }
 
     const auto difference = feedback.timestamp - swap_time;
@@ -556,7 +560,7 @@ void Display::DidReceivePresentationFeedback(
   }
 #endif
   for (auto& callback : callbacks) {
-    std::move(callback).Run(feedback);
+    std::move(callback).Run(copy_feedback);
   }
   pending_presented_callbacks_.pop_front();
 }

content/renderer/gpu/layer_tree_view.cc

@@ -12,6 +12,7 @@
 #include "base/callback.h"
 #include "base/feature_list.h"
 #include "base/location.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/single_thread_task_runner.h"
 #include "base/task/post_task.h"
 #include "base/task/task_scheduler/task_scheduler.h"
@@ -58,12 +59,23 @@ namespace {
 
 using ReportTimeCallback = blink::WebLayerTreeView::ReportTimeCallback;
 
-// Enables using presentation times instead of swap times in swap promises.
-// Currently, these promises are only used by Paint Timing, but they will be
-// used by other APIs such as Event Timing.
-const base::Feature kUsePresentationTimeInSwapPromise = {
-    "UsePresentationTimeInSwapPromise", base::FEATURE_DISABLED_BY_DEFAULT};
+void RecordSwapTimeToPresentationTime(base::TimeTicks swap_time,
+                                      base::TimeTicks presentation_time) {
+  DCHECK(!swap_time.is_null());
+  bool presentation_time_is_valid =
+      !presentation_time.is_null() && (presentation_time > swap_time);
+  UMA_HISTOGRAM_BOOLEAN("PageLoad.Internal.Renderer.PresentationTime.Valid",
+                        presentation_time_is_valid);
+  if (presentation_time_is_valid) {
+    // This measures from 1ms to 10seconds.
+    UMA_HISTOGRAM_TIMES(
+        "PageLoad.Internal.Renderer.PresentationTime.DeltaFromSwapTime",
+        presentation_time - swap_time);
+  }
+}
 
+// Enables measuring and reporting both presentation times and swap times in
+// swap promises.
 class ReportTimeSwapPromise : public cc::SwapPromise {
  public:
   ReportTimeSwapPromise(ReportTimeCallback callback,
@@ -81,6 +93,7 @@ class ReportTimeSwapPromise : public cc::SwapPromise {
   ReportTimeCallback callback_;
   scoped_refptr<base::SingleThreadTaskRunner> task_runner_;
   base::WeakPtr<LayerTreeView> layer_tree_view_;
+  uint32_t frame_token_ = 0;
 
   DISALLOW_COPY_AND_ASSIGN(ReportTimeSwapPromise);
 };
@@ -97,31 +110,30 @@ ReportTimeSwapPromise::~ReportTimeSwapPromise() {}
 
 void ReportTimeSwapPromise::WillSwap(viz::CompositorFrameMetadata* metadata) {
   DCHECK_GT(metadata->frame_token, 0u);
+  // Request a presentation timestamp for this frame. The interval between the
+  // current swap and its presentation time is reported in UMA (see
+  // corresponding code in DidSwap() below).
   metadata->request_presentation_feedback = true;
-  if (!base::FeatureList::IsEnabled(kUsePresentationTimeInSwapPromise))
-    return;
-
-  // If using presentation timestamp, post task here calling
-  // LayerTreeView::AddPresentationCallback.
-  auto* task_runner = task_runner_.get();
-  task_runner->PostTask(
-      FROM_HERE,
-      base::BindOnce(
-          &LayerTreeView::AddPresentationCallback, layer_tree_view_,
-          metadata->frame_token,
-          base::BindOnce(std::move(callback_),
-                         blink::WebLayerTreeView::SwapResult::kDidSwap)));
+  frame_token_ = metadata->frame_token;
 }
 
 void ReportTimeSwapPromise::DidSwap() {
-  if (base::FeatureList::IsEnabled(kUsePresentationTimeInSwapPromise))
-    return;
-
-  // If using swap timestamp, the swap promise should return the current time.
+  DCHECK_GT(frame_token_, 0u);
   task_runner_->PostTask(
-      FROM_HERE, base::BindOnce(std::move(callback_),
-                                blink::WebLayerTreeView::SwapResult::kDidSwap,
-                                base::TimeTicks::Now()));
+      FROM_HERE,
+      base::BindOnce(
+          [](base::TimeTicks timestamp, ReportTimeCallback callback,
+             base::WeakPtr<LayerTreeView> layer_tree_view, int frame_token) {
+            std::move(callback).Run(
+                blink::WebLayerTreeView::SwapResult::kDidSwap, timestamp);
+            if (layer_tree_view) {
+              layer_tree_view->AddPresentationCallback(
+                  frame_token,
+                  base::BindOnce(&RecordSwapTimeToPresentationTime, timestamp));
+            }
+          },
+          base::TimeTicks::Now(), std::move(callback_), layer_tree_view_,
+          frame_token_));
 }
 
 void ReportTimeSwapPromise::DidNotSwap(

content/renderer/gpu/layer_tree_view_unittest.cc

@@ -10,14 +10,17 @@
 #include "base/macros.h"
 #include "base/run_loop.h"
 #include "base/single_thread_task_runner.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "base/test/scoped_task_environment.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "build/build_config.h"
+#include "cc/layers/solid_color_layer.h"
 #include "cc/test/fake_layer_tree_frame_sink.h"
 #include "cc/test/test_task_graph_runner.h"
 #include "cc/test/test_ukm_recorder_factory.h"
 #include "cc/trees/layer_tree_host.h"
 #include "components/viz/common/frame_sinks/copy_output_request.h"
+#include "components/viz/common/surfaces/parent_local_surface_id_allocator.h"
 #include "components/viz/test/test_context_provider.h"
 #include "content/test/stub_layer_tree_view_delegate.h"
 #include "gpu/GLES2/gl2extchromium.h"
@@ -372,5 +375,123 @@ TEST(LayerTreeViewTest, VisibilityTest) {
   }
 }
 
+class NotifySwapTimesLayerTreeViewTest : public ::testing::Test {
+ public:
+  NotifySwapTimesLayerTreeViewTest()
+      : layer_tree_view_(
+            &layer_tree_view_delegate_,
+            blink::scheduler::GetSingleThreadTaskRunnerForTesting(),
+            nullptr /* compositor_thread */,
+            &test_task_graph_runner_,
+            &fake_renderer_scheduler_) {
+    layer_tree_view_delegate_.add_request();
+  }
+
+  void SetUp() override {
+    cc::LayerTreeSettings settings;
+    settings.single_thread_proxy_scheduler = false;
+    layer_tree_view_.Initialize(settings,
+                                std::make_unique<cc::TestUkmRecorderFactory>());
+
+    viz::ParentLocalSurfaceIdAllocator allocator;
+    layer_tree_view_.SetVisible(true);
+    layer_tree_view_.SetViewportSizeAndScale(
+        gfx::Size(200, 100), 1.f,
+        allocator.GetCurrentLocalSurfaceIdAllocation());
+
+    auto root_layer = cc::SolidColorLayer::Create();
+    root_layer->SetBounds(gfx::Size(200, 100));
+    root_layer->SetBackgroundColor(SK_ColorGREEN);
+    layer_tree_view_.layer_tree_host()->SetRootLayer(root_layer);
+
+    auto color_layer = cc::SolidColorLayer::Create();
+    color_layer->SetBounds(gfx::Size(100, 100));
+    root_layer->AddChild(color_layer);
+    color_layer->SetBackgroundColor(SK_ColorRED);
+  }
+
+  base::TimeTicks CompositeAndReturnSwapTimestamp() {
+    base::TimeTicks swap_time;
+    base::RunLoop run_loop;
+    layer_tree_view_.NotifySwapTime(base::BindOnce(
+        [](base::OnceClosure callback, base::TimeTicks* swap_time,
+           blink::WebLayerTreeView::SwapResult result,
+           base::TimeTicks timestamp) {
+          *swap_time = timestamp;
+          std::move(callback).Run();
+        },
+        run_loop.QuitClosure(), &swap_time));
+    blink::scheduler::GetSingleThreadTaskRunnerForTesting()->PostTask(
+        FROM_HERE,
+        base::BindOnce(
+            &LayerTreeView::UpdateAllLifecyclePhasesAndCompositeForTesting,
+            base::Unretained(&layer_tree_view_), true /* do_raster */));
+    run_loop.Run();
+    return swap_time;
+  }
+
+ protected:
+  base::test::ScopedTaskEnvironment task_environment_;
+  cc::TestTaskGraphRunner test_task_graph_runner_;
+  blink::scheduler::FakeRendererScheduler fake_renderer_scheduler_;
+  FakeLayerTreeViewDelegate layer_tree_view_delegate_;
+  LayerTreeView layer_tree_view_;
+};
+
+TEST_F(NotifySwapTimesLayerTreeViewTest, PresentationTimestampValid) {
+  base::HistogramTester histograms;
+
+  base::TimeTicks swap_time = CompositeAndReturnSwapTimestamp();
+  ASSERT_FALSE(swap_time.is_null());
+
+  layer_tree_view_.DidPresentCompositorFrame(
+      1, gfx::PresentationFeedback(
+             swap_time + base::TimeDelta::FromMilliseconds(2),
+             base::TimeDelta::FromMilliseconds(16), 0));
+  EXPECT_THAT(histograms.GetAllSamples(
+                  "PageLoad.Internal.Renderer.PresentationTime.Valid"),
+              testing::ElementsAre(base::Bucket(true, 1)));
+  EXPECT_THAT(
+      histograms.GetAllSamples(
+          "PageLoad.Internal.Renderer.PresentationTime.DeltaFromSwapTime"),
+      testing::ElementsAre(base::Bucket(2, 1)));
+}
+
+TEST_F(NotifySwapTimesLayerTreeViewTest, PresentationTimestampInvalid) {
+  base::HistogramTester histograms;
+
+  base::TimeTicks swap_time = CompositeAndReturnSwapTimestamp();
+  ASSERT_FALSE(swap_time.is_null());
+
+  layer_tree_view_.DidPresentCompositorFrame(1, gfx::PresentationFeedback());
+  EXPECT_THAT(histograms.GetAllSamples(
+                  "PageLoad.Internal.Renderer.PresentationTime.Valid"),
+              testing::ElementsAre(base::Bucket(false, 1)));
+  EXPECT_THAT(
+      histograms.GetAllSamples(
+          "PageLoad.Internal.Renderer.PresentationTime.DeltaFromSwapTime"),
+      testing::IsEmpty());
+}
+
+TEST_F(NotifySwapTimesLayerTreeViewTest,
+       PresentationTimestampEarlierThanSwaptime) {
+  base::HistogramTester histograms;
+
+  base::TimeTicks swap_time = CompositeAndReturnSwapTimestamp();
+  ASSERT_FALSE(swap_time.is_null());
+
+  layer_tree_view_.DidPresentCompositorFrame(
+      1, gfx::PresentationFeedback(
+             swap_time - base::TimeDelta::FromMilliseconds(2),
+             base::TimeDelta::FromMilliseconds(16), 0));
+  EXPECT_THAT(histograms.GetAllSamples(
+                  "PageLoad.Internal.Renderer.PresentationTime.Valid"),
+              testing::ElementsAre(base::Bucket(false, 1)));
+  EXPECT_THAT(
+      histograms.GetAllSamples(
+          "PageLoad.Internal.Renderer.PresentationTime.DeltaFromSwapTime"),
+      testing::IsEmpty());
+}
+
 }  // namespace
 }  // namespace content

tools/metrics/histograms/histograms.xml

@@ -74084,6 +74084,33 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="PageLoad.Internal.Renderer.PresentationTime.DeltaFromSwapTime"
+    units="ms">
+  <owner>sadrul@chromium.org</owner>
+  <summary>
+    'Swap time' is the timestamp of the renderer submitting a CompositorFrame,
+    and 'Presentation time' is the timestamp of the frame becoming visible on
+    screen. This metric measures the duration between the swap-time and the
+    presentation-time. This is recorded only if a valid presentation-timestamp
+    is available. See PageLoad.Internal.Renderer.PresentationTime.Valid for how
+    often the presentation-timestamp is valid. This is reported only for
+    compositor-frames that report a paint-timing metric (e.g.
+    FirstContentfulPaint etc.), and after that frame has been displayed on
+    screen.
+  </summary>
+</histogram>
+
+<histogram name="PageLoad.Internal.Renderer.PresentationTime.Valid"
+    enum="Boolean">
+  <owner>sadrul@chromium.org</owner>
+  <summary>
+    This boolean keeps track of whether a valid presentation-timestamp was
+    received or not. This is reported only for compositor-frames that report a
+    paint-timing metric (e.g. FirstContentfulPaint etc.), and after that frame
+    has been displayed on screen.
+  </summary>
+</histogram>
+
 <histogram name="PageLoad.Navigation.RedirectChainLength" units="urls">
   <owner>csharrison@chromium.org</owner>
   <summary>