[Sampling profiler] Reland "Apply metadata to samples before first contentful paint"

Requests that the sampling profiler apply metadata to samples between
navigation start and first contentful paint, at the time when first
contentful paint is sent to the browser process. This metadata will
support analysis of execution during page load.

This change introduces monotonic time interfaces for the required metrics
because the existing interfaces are limited to 1ms resolution. If used
they would result in up to 2% of samples being misidentified as occurring
during loading when they weren't, or vice versa.

This is a reland of http://crrev.com/742717 and adds logic to avoid
applying metadata on time ranges that don't make sense but are
occasionally seen in practice.

TBR=npm@chromium.org,schenney@chromium.org

Bug: 1034756, 1054357
Change-Id: Ie7e7a26b4e2c86219eb30dd678e5de296d2f59be
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2067287Reviewed-by: Mike Wittman <wittman@chromium.org>
Reviewed-by: Nicolás Peña Moreno <npm@chromium.org>
Reviewed-by: Bryan McQuade <bmcquade@chromium.org>
Commit-Queue: Mike Wittman <wittman@chromium.org>
Cr-Commit-Position: refs/heads/master@{#744852}

components/page_load_metrics/renderer/BUILD.gn

@@ -8,6 +8,8 @@ source_set("renderer") {
     "metrics_render_frame_observer.h",
     "page_resource_data_use.cc",
     "page_resource_data_use.h",
+    "page_timing_metadata_recorder.cc",
+    "page_timing_metadata_recorder.h",
     "page_timing_metrics_sender.cc",
     "page_timing_metrics_sender.h",
     "page_timing_sender.h",

components/page_load_metrics/renderer/metrics_render_frame_observer.cc

@@ -32,6 +32,10 @@ base::TimeDelta ClampDelta(double event, double start) {
   return base::Time::FromDoubleT(event) - base::Time::FromDoubleT(start);
 }
 
+base::TimeTicks ClampToStart(base::TimeTicks event, base::TimeTicks start) {
+  return event < start ? start : event;
+}
+
 class MojoPageTimingSender : public PageTimingSender {
  public:
   explicit MojoPageTimingSender(content::RenderFrame* render_frame) {
@@ -252,8 +256,10 @@ void MetricsRenderFrameObserver::DidCommitProvisionalLoad(
   provisional_frame_resource_id_ =
       provisional_frame_resource_data_use_->resource_id();
 
+  Timing timing = GetTiming();
   page_timing_metrics_sender_ = std::make_unique<PageTimingMetricsSender>(
-      CreatePageTimingSender(), CreateTimer(), GetTiming(),
+      CreatePageTimingSender(), CreateTimer(),
+      std::move(timing.relative_timing), timing.monotonic_timing,
       std::move(provisional_frame_resource_data_use_));
 }
 
@@ -295,6 +301,18 @@ void MetricsRenderFrameObserver::MaybeSetCompletedBeforeFCP(int request_id) {
     before_fcp_request_ids_.insert(request_id);
 }
 
+MetricsRenderFrameObserver::Timing::Timing(
+    mojom::PageLoadTimingPtr relative_timing,
+    const PageTimingMetadataRecorder::MonotonicTiming& monotonic_timing)
+    : relative_timing(std::move(relative_timing)),
+      monotonic_timing(monotonic_timing) {}
+
+MetricsRenderFrameObserver::Timing::~Timing() = default;
+
+MetricsRenderFrameObserver::Timing::Timing(Timing&&) = default;
+MetricsRenderFrameObserver::Timing& MetricsRenderFrameObserver::Timing::
+operator=(Timing&&) = default;
+
 void MetricsRenderFrameObserver::UpdateResourceMetadata(int request_id) {
   if (!page_timing_metrics_sender_)
     return;
@@ -336,16 +354,21 @@ void MetricsRenderFrameObserver::SendMetrics() {
     return;
   if (HasNoRenderFrame())
     return;
-  page_timing_metrics_sender_->SendSoon(GetTiming());
+  Timing timing = GetTiming();
+  page_timing_metrics_sender_->Update(std::move(timing.relative_timing),
+                                      timing.monotonic_timing);
 }
 
-mojom::PageLoadTimingPtr MetricsRenderFrameObserver::GetTiming() const {
+MetricsRenderFrameObserver::Timing MetricsRenderFrameObserver::GetTiming()
+    const {
   const blink::WebPerformance& perf =
       render_frame()->GetWebFrame()->Performance();
 
   mojom::PageLoadTimingPtr timing(CreatePageLoadTiming());
+  PageTimingMetadataRecorder::MonotonicTiming monotonic_timing;
   double start = perf.NavigationStart();
   timing->navigation_start = base::Time::FromDoubleT(start);
+  monotonic_timing.navigation_start = perf.NavigationStartAsMonotonicTime();
   if (perf.InputForNavigationStart() > 0.0) {
     timing->input_to_navigation_start =
         ClampDelta(start, perf.InputForNavigationStart());
@@ -409,6 +432,9 @@ mojom::PageLoadTimingPtr MetricsRenderFrameObserver::GetTiming() const {
   if (perf.FirstContentfulPaint() > 0.0) {
     timing->paint_timing->first_contentful_paint =
         ClampDelta(perf.FirstContentfulPaint(), start);
+    monotonic_timing.first_contentful_paint =
+        ClampToStart(perf.FirstContentfulPaintAsMonotonicTime(),
+                     perf.NavigationStartAsMonotonicTime());
   }
   if (perf.FirstMeaningfulPaint() > 0.0) {
     timing->paint_timing->first_meaningful_paint =
@@ -458,7 +484,7 @@ mojom::PageLoadTimingPtr MetricsRenderFrameObserver::GetTiming() const {
             perf.ParseBlockedOnScriptExecutionFromDocumentWriteDuration());
   }
 
-  return timing;
+  return Timing(std::move(timing), monotonic_timing);
 }
 
 std::unique_ptr<base::OneShotTimer> MetricsRenderFrameObserver::CreateTimer() {

components/page_load_metrics/renderer/metrics_render_frame_observer.h

@@ -12,6 +12,7 @@
 #include "base/scoped_observer.h"
 #include "components/page_load_metrics/common/page_load_timing.h"
 #include "components/page_load_metrics/renderer/page_resource_data_use.h"
+#include "components/page_load_metrics/renderer/page_timing_metadata_recorder.h"
 #include "components/subresource_filter/content/renderer/ad_resource_tracker.h"
 #include "content/public/renderer/render_frame_observer.h"
 #include "third_party/blink/public/common/loader/loading_behavior_flag.h"
@@ -86,6 +87,22 @@ class MetricsRenderFrameObserver
   void OnAdResourceTrackerGoingAway() override;
   void OnAdResourceObserved(int request_id) override;
 
+ protected:
+  // The relative and monotonic page load timings.
+  struct Timing {
+    Timing(mojom::PageLoadTimingPtr relative_timing,
+           const PageTimingMetadataRecorder::MonotonicTiming& monotonic_timing);
+    ~Timing();
+
+    Timing(const Timing&) = delete;
+    Timing& operator=(const Timing&) = delete;
+    Timing(Timing&&);
+    Timing& operator=(Timing&&);
+
+    mojom::PageLoadTimingPtr relative_timing;
+    PageTimingMetadataRecorder::MonotonicTiming monotonic_timing;
+  };
+
  private:
   // Updates the metadata for the page resource associated with the given
   // request_id. Removes the request_id from the list of known ads if it is an
@@ -97,7 +114,7 @@ class MetricsRenderFrameObserver
   void MaybeSetCompletedBeforeFCP(int request_id);
 
   void SendMetrics();
-  virtual mojom::PageLoadTimingPtr GetTiming() const;
+  virtual Timing GetTiming() const;
   virtual std::unique_ptr<base::OneShotTimer> CreateTimer();
   virtual std::unique_ptr<PageTimingSender> CreatePageTimingSender();
   virtual bool HasNoRenderFrame() const;

components/page_load_metrics/renderer/metrics_render_frame_observer_unittest.cc

@@ -51,9 +51,10 @@ class TestMetricsRenderFrameObserver : public MetricsRenderFrameObserver,
     fake_timing_ = timing.Clone();
   }
 
-  mojom::PageLoadTimingPtr GetTiming() const override {
+  Timing GetTiming() const override {
     EXPECT_NE(nullptr, fake_timing_.get());
-    return std::move(fake_timing_);
+    return Timing(std::move(fake_timing_),
+                  PageTimingMetadataRecorder::MonotonicTiming());
   }
 
   void VerifyExpectedTimings() const {

components/page_load_metrics/renderer/page_timing_metadata_recorder.cc

+// Copyright 2020 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 "components/page_load_metrics/renderer/page_timing_metadata_recorder.h"
+
+#include "base/profiler/sample_metadata.h"
+
+namespace page_load_metrics {
+
+namespace {
+bool IsTimeTicksRangeSensible(base::TimeTicks start, base::TimeTicks end) {
+  return start <= end && end <= base::TimeTicks::Now();
+}
+}  // namespace
+
+// The next instance id to use for a PageTimingMetadataRecorder.
+int g_next_instance_id = 1;
+
+PageTimingMetadataRecorder::MonotonicTiming::MonotonicTiming() = default;
+PageTimingMetadataRecorder::MonotonicTiming::MonotonicTiming(
+    const MonotonicTiming&) = default;
+PageTimingMetadataRecorder::MonotonicTiming&
+PageTimingMetadataRecorder::MonotonicTiming::operator=(const MonotonicTiming&) =
+    default;
+PageTimingMetadataRecorder::MonotonicTiming::MonotonicTiming(
+    MonotonicTiming&&) = default;
+PageTimingMetadataRecorder::MonotonicTiming&
+PageTimingMetadataRecorder::MonotonicTiming::operator=(MonotonicTiming&&) =
+    default;
+
+PageTimingMetadataRecorder::PageTimingMetadataRecorder(
+    const MonotonicTiming& initial_timing)
+    : instance_id_(g_next_instance_id++) {
+  UpdateMetadata(initial_timing);
+}
+
+PageTimingMetadataRecorder::~PageTimingMetadataRecorder() = default;
+
+void PageTimingMetadataRecorder::UpdateMetadata(const MonotonicTiming& timing) {
+  // Applying metadata to past samples has non-trivial cost so only do so if
+  // the relevant values changed.
+  const bool should_apply_metadata =
+      timing.navigation_start.has_value() &&
+      timing.first_contentful_paint.has_value() &&
+      (timing_.navigation_start != timing.navigation_start ||
+       timing_.first_contentful_paint != timing.first_contentful_paint);
+  if (should_apply_metadata &&
+      IsTimeTicksRangeSensible(*timing.navigation_start,
+                               *timing.first_contentful_paint)) {
+    base::ApplyMetadataToPastSamples(
+        *timing.navigation_start, *timing.first_contentful_paint,
+        "PageLoad.PaintTiming.NavigationToFirstContentfulPaint", instance_id_,
+        1);
+  }
+
+  timing_ = timing;
+}
+
+}  // namespace page_load_metrics

components/page_load_metrics/renderer/page_timing_metadata_recorder.h

+// Copyright 2020 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.
+
+#ifndef COMPONENTS_PAGE_LOAD_METRICS_RENDERER_PAGE_TIMING_METADATA_RECORDER_H_
+#define COMPONENTS_PAGE_LOAD_METRICS_RENDERER_PAGE_TIMING_METADATA_RECORDER_H_
+
+#include "base/optional.h"
+#include "base/time/time.h"
+
+namespace page_load_metrics {
+
+// Records metadata corresponding to page load metrics on sampling profiler
+// stack samples. PageTimingMetadataRecorder is currently only intended to be
+// used for the sampling profiler. If you have a new use case in mind, please
+// reach out to page_load_metrics owners to discuss it.
+class PageTimingMetadataRecorder {
+ public:
+  // Records the monotonic times that define first contentful paint.
+  struct MonotonicTiming {
+    MonotonicTiming();
+
+    MonotonicTiming(const MonotonicTiming&);
+    MonotonicTiming& operator=(const MonotonicTiming&);
+    MonotonicTiming(MonotonicTiming&&);
+    MonotonicTiming& operator=(MonotonicTiming&&);
+
+    base::Optional<base::TimeTicks> navigation_start;
+    base::Optional<base::TimeTicks> first_contentful_paint;
+  };
+
+  PageTimingMetadataRecorder(const MonotonicTiming& initial_timing);
+  ~PageTimingMetadataRecorder();
+
+  PageTimingMetadataRecorder(const PageTimingMetadataRecorder&) = delete;
+  PageTimingMetadataRecorder& operator=(const PageTimingMetadataRecorder&) =
+      delete;
+
+  void UpdateMetadata(const MonotonicTiming& timing);
+
+ private:
+  // Uniquely identifies an instance of the PageTimingMetadataRecorder. Used to
+  // distinguish page loads for different documents when applying sample
+  // metadata.
+  const int instance_id_;
+
+  // Records the monotonic times that define first contentful paint.
+  MonotonicTiming timing_;
+};
+
+}  // namespace page_load_metrics
+
+#endif  // COMPONENTS_PAGE_LOAD_METRICS_RENDERER_PAGE_TIMING_METADATA_RECORDER_H_

components/page_load_metrics/renderer/page_timing_metrics_sender.cc

@@ -30,6 +30,7 @@ PageTimingMetricsSender::PageTimingMetricsSender(
     std::unique_ptr<PageTimingSender> sender,
     std::unique_ptr<base::OneShotTimer> timer,
     mojom::PageLoadTimingPtr initial_timing,
+    const PageTimingMetadataRecorder::MonotonicTiming& initial_monotonic_timing,
     std::unique_ptr<PageResourceDataUse> initial_request)
     : sender_(std::move(sender)),
       timer_(std::move(timer)),
@@ -39,7 +40,8 @@ PageTimingMetricsSender::PageTimingMetricsSender(
       new_features_(mojom::PageLoadFeatures::New()),
       render_data_(),
       new_deferred_resource_data_(mojom::DeferredResourceCounts::New()),
-      buffer_timer_delay_ms_(kBufferTimerDelayMillis) {
+      buffer_timer_delay_ms_(kBufferTimerDelayMillis),
+      metadata_recorder_(initial_monotonic_timing) {
   page_resource_data_use_.emplace(
       std::piecewise_construct,
       std::forward_as_tuple(initial_request->resource_id()),
@@ -226,7 +228,9 @@ void PageTimingMetricsSender::UpdateResourceMetadata(
   it->second->SetIsMainFrameResource(is_main_frame_resource);
 }
 
-void PageTimingMetricsSender::SendSoon(mojom::PageLoadTimingPtr timing) {
+void PageTimingMetricsSender::Update(
+    mojom::PageLoadTimingPtr timing,
+    const PageTimingMetadataRecorder::MonotonicTiming& monotonic_timing) {
   if (last_timing_->Equals(*timing)) {
     return;
   }
@@ -240,6 +244,7 @@ void PageTimingMetricsSender::SendSoon(mojom::PageLoadTimingPtr timing) {
   }
 
   last_timing_ = std::move(timing);
+  metadata_recorder_.UpdateMetadata(monotonic_timing);
   EnsureSendTimer();
 }
 

components/page_load_metrics/renderer/page_timing_metrics_sender.h

@@ -13,6 +13,7 @@
 #include "base/macros.h"
 #include "components/page_load_metrics/common/page_load_timing.h"
 #include "components/page_load_metrics/renderer/page_resource_data_use.h"
+#include "components/page_load_metrics/renderer/page_timing_metadata_recorder.h"
 #include "content/public/common/previews_state.h"
 #include "services/network/public/mojom/url_response_head.mojom-forward.h"
 #include "third_party/blink/public/common/loader/loading_behavior_flag.h"
@@ -42,6 +43,8 @@ class PageTimingMetricsSender {
   PageTimingMetricsSender(std::unique_ptr<PageTimingSender> sender,
                           std::unique_ptr<base::OneShotTimer> timer,
                           mojom::PageLoadTimingPtr initial_timing,
+                          const PageTimingMetadataRecorder::MonotonicTiming&
+                              initial_monotonic_timing,
                           std::unique_ptr<PageResourceDataUse> initial_request);
   ~PageTimingMetricsSender();
 
@@ -67,8 +70,11 @@ class PageTimingMetricsSender {
                                       int64_t encoded_body_length,
                                       const std::string& mime_type);
 
-  // Queues the send by starting the send timer.
-  void SendSoon(mojom::PageLoadTimingPtr timing);
+  // Updates the timing information. Buffers |timing| to be sent over mojo
+  // sometime 'soon'.
+  void Update(
+      mojom::PageLoadTimingPtr timing,
+      const PageTimingMetadataRecorder::MonotonicTiming& monotonic_timing);
 
   // Sends any queued timing data immediately and stops the send timer.
   void SendLatest();
@@ -125,6 +131,10 @@ class PageTimingMetricsSender {
   // https://crbug.com/847269.
   int buffer_timer_delay_ms_;
 
+  // Responsible for recording sampling profiler metadata corresponding to page
+  // timing.
+  PageTimingMetadataRecorder metadata_recorder_;
+
   DISALLOW_COPY_AND_ASSIGN(PageTimingMetricsSender);
 };
 

third_party/blink/public/web/web_performance.h

@@ -31,6 +31,7 @@
 #ifndef THIRD_PARTY_BLINK_PUBLIC_WEB_WEB_PERFORMANCE_H_
 #define THIRD_PARTY_BLINK_PUBLIC_WEB_WEB_PERFORMANCE_H_
 
+#include "base/time/time.h"
 #include "third_party/blink/public/platform/web_common.h"
 #include "third_party/blink/public/platform/web_private_ptr.h"
 #include "third_party/blink/public/web/web_navigation_type.h"
@@ -66,6 +67,7 @@ class WebPerformance {
   // These functions return time in seconds (not milliseconds) since the epoch.
   BLINK_EXPORT double InputForNavigationStart() const;
   BLINK_EXPORT double NavigationStart() const;
+  BLINK_EXPORT base::TimeTicks NavigationStartAsMonotonicTime() const;
   BLINK_EXPORT double UnloadEventEnd() const;
   BLINK_EXPORT double RedirectStart() const;
   BLINK_EXPORT double RedirectEnd() const;
@@ -88,6 +90,7 @@ class WebPerformance {
   BLINK_EXPORT double FirstPaint() const;
   BLINK_EXPORT double FirstImagePaint() const;
   BLINK_EXPORT double FirstContentfulPaint() const;
+  BLINK_EXPORT base::TimeTicks FirstContentfulPaintAsMonotonicTime() const;
   BLINK_EXPORT double FirstMeaningfulPaint() const;
   BLINK_EXPORT double FirstMeaningfulPaintCandidate() const;
   BLINK_EXPORT double LargestImagePaint() const;

third_party/blink/renderer/core/exported/web_performance.cc

@@ -65,6 +65,10 @@ double WebPerformance::NavigationStart() const {
   return MillisecondsToSeconds(private_->timing()->navigationStart());
 }
 
+base::TimeTicks WebPerformance::NavigationStartAsMonotonicTime() const {
+  return private_->timing()->NavigationStartAsMonotonicTime();
+}
+
 double WebPerformance::InputForNavigationStart() const {
   return MillisecondsToSeconds(private_->timing()->inputStart());
 }
@@ -158,6 +162,10 @@ double WebPerformance::FirstContentfulPaint() const {
   return MillisecondsToSeconds(private_->timing()->FirstContentfulPaint());
 }
 
+base::TimeTicks WebPerformance::FirstContentfulPaintAsMonotonicTime() const {
+  return private_->timing()->FirstContentfulPaintAsMonotonicTime();
+}
+
 double WebPerformance::FirstMeaningfulPaint() const {
   return MillisecondsToSeconds(private_->timing()->FirstMeaningfulPaint());
 }

third_party/blink/renderer/core/timing/performance_timing.cc

@@ -311,6 +311,14 @@ uint64_t PerformanceTiming::loadEventEnd() const {
   return MonotonicTimeToIntegerMilliseconds(timing->LoadEventEnd());
 }
 
+base::TimeTicks PerformanceTiming::NavigationStartAsMonotonicTime() const {
+  DocumentLoadTiming* timing = GetDocumentLoadTiming();
+  if (!timing)
+    return base::TimeTicks();
+
+  return timing->NavigationStart();
+}
+
 uint64_t PerformanceTiming::FirstPaint() const {
   const PaintTiming* timing = GetPaintTiming();
   if (!timing)
@@ -335,6 +343,14 @@ uint64_t PerformanceTiming::FirstContentfulPaint() const {
   return MonotonicTimeToIntegerMilliseconds(timing->FirstContentfulPaint());
 }
 
+base::TimeTicks PerformanceTiming::FirstContentfulPaintAsMonotonicTime() const {
+  const PaintTiming* timing = GetPaintTiming();
+  if (!timing)
+    return base::TimeTicks();
+
+  return timing->FirstContentfulPaint();
+}
+
 uint64_t PerformanceTiming::FirstMeaningfulPaint() const {
   const PaintTiming* timing = GetPaintTiming();
   if (!timing)

third_party/blink/renderer/core/timing/performance_timing.h

@@ -31,6 +31,7 @@
 #ifndef THIRD_PARTY_BLINK_RENDERER_CORE_TIMING_PERFORMANCE_TIMING_H_
 #define THIRD_PARTY_BLINK_RENDERER_CORE_TIMING_PERFORMANCE_TIMING_H_
 
+#include "base/time/time.h"
 #include "third_party/blink/renderer/core/core_export.h"
 #include "third_party/blink/renderer/core/execution_context/execution_context_lifecycle_observer.h"
 #include "third_party/blink/renderer/platform/bindings/script_wrappable.h"
@@ -86,6 +87,11 @@ class CORE_EXPORT PerformanceTiming final : public ScriptWrappable,
 
   // The below are non-spec timings, for Page Load UMA metrics.
 
+  // The time immediately after the user agent finishes prompting to unload the
+  // previous document, or if there is no previous document, the same value as
+  // fetchStart.  Intended to be used for correlation with other events internal
+  // to blink. Not to be exposed to JavaScript.
+  base::TimeTicks NavigationStartAsMonotonicTime() const;
   // The time the first paint operation was performed.
   uint64_t FirstPaint() const;
   // The time the first paint operation for image was performed.
@@ -93,6 +99,10 @@ class CORE_EXPORT PerformanceTiming final : public ScriptWrappable,
   // The time of the first 'contentful' paint. A contentful paint is a paint
   // that includes content of some kind (for example, text or image content).
   uint64_t FirstContentfulPaint() const;
+  // The first 'contentful' paint as full-resolution monotonic time. Intended to
+  // be used for correlation with other events internal to blink. Not to be
+  // exposed to JavaScript.
+  base::TimeTicks FirstContentfulPaintAsMonotonicTime() const;
   // The time of the first 'meaningful' paint, A meaningful paint is a paint
   // where the page's primary content is visible.
   uint64_t FirstMeaningfulPaint() const;