BackForwardCache Record requestAnimationFrame times after BFcache restores

This CL adds new metrics to record the timing on requestAnimationFrame
three times after the page is restored from BFcache. These values can be
good approximation for the first paint after BFcache restores, and we
want to confirm this.

BUG: 1133333
BUG: 1152688
Change-Id: Ib7fe363bf6ac20f07308bd90eb940530fcd49df1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2523133
Commit-Queue: Hajime Hoshi <hajimehoshi@chromium.org>
Reviewed-by: Kinuko Yasuda <kinuko@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Nicolás Peña Moreno <npm@chromium.org>
Reviewed-by: Annie Sullivan <sullivan@chromium.org>
Reviewed-by: Alexander Timin <altimin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#830919}

components/page_load_metrics/browser/observers/back_forward_cache_page_load_metrics_observer.cc

@@ -12,6 +12,12 @@ namespace internal {
 
 const char kHistogramFirstPaintAfterBackForwardCacheRestore[] =
     "PageLoad.PaintTiming.NavigationToFirstPaint.AfterBackForwardCacheRestore";
+const char kHistogramFirstRequestAnimationFrameAfterBackForwardCacheRestore[] =
+    "PageLoad.PaintTiming.NavigationToFirstPaint.BFCachePolyfillFirst";
+const char kHistogramSecondRequestAnimationFrameAfterBackForwardCacheRestore[] =
+    "PageLoad.PaintTiming.NavigationToFirstPaint.BFCachePolyfillSecond";
+const char kHistogramThirdRequestAnimationFrameAfterBackForwardCacheRestore[] =
+    "PageLoad.PaintTiming.NavigationToFirstPaint.BFCachePolyfillThird";
 const char kHistogramFirstInputDelayAfterBackForwardCacheRestore[] =
     "PageLoad.InteractiveTiming.FirstInputDelay.AfterBackForwardCacheRestore";
 extern const char
@@ -97,6 +103,27 @@ void BackForwardCachePageLoadMetricsObserver::
   }
 }
 
+void BackForwardCachePageLoadMetricsObserver::
+    OnRequestAnimationFramesAfterBackForwardCacheRestoreInPage(
+        const page_load_metrics::mojom::BackForwardCacheTiming& timing) {
+  auto request_animation_frames =
+      timing.request_animation_frames_after_back_forward_cache_restore;
+  DCHECK_EQ(request_animation_frames.size(), 3u);
+
+  PAGE_LOAD_HISTOGRAM(
+      internal::
+          kHistogramFirstRequestAnimationFrameAfterBackForwardCacheRestore,
+      request_animation_frames[0]);
+  PAGE_LOAD_HISTOGRAM(
+      internal::
+          kHistogramSecondRequestAnimationFrameAfterBackForwardCacheRestore,
+      request_animation_frames[1]);
+  PAGE_LOAD_HISTOGRAM(
+      internal::
+          kHistogramThirdRequestAnimationFrameAfterBackForwardCacheRestore,
+      request_animation_frames[2]);
+}
+
 void BackForwardCachePageLoadMetricsObserver::
     OnFirstInputAfterBackForwardCacheRestoreInPage(
         const page_load_metrics::mojom::BackForwardCacheTiming& timing,

components/page_load_metrics/browser/observers/back_forward_cache_page_load_metrics_observer.h

@@ -35,6 +35,8 @@ class BackForwardCachePageLoadMetricsObserver
   void OnFirstPaintAfterBackForwardCacheRestoreInPage(
       const page_load_metrics::mojom::BackForwardCacheTiming& timing,
       size_t index) override;
+  void OnRequestAnimationFramesAfterBackForwardCacheRestoreInPage(
+      const page_load_metrics::mojom::BackForwardCacheTiming& timing) override;
   void OnFirstInputAfterBackForwardCacheRestoreInPage(
       const page_load_metrics::mojom::BackForwardCacheTiming& timing,
       size_t index) override;

components/page_load_metrics/browser/page_load_metrics_observer.h

@@ -375,6 +375,13 @@ class PageLoadMetricsObserver {
       const mojom::BackForwardCacheTiming& timing,
       size_t index) {}
 
+  // This is called several times on requestAnimationFrame after the page is
+  // restored from the back-forward cache. The number of the calls is hard-
+  // coded as WebPerformance::
+  // kRequestAnimationFramesToRecordAfterBackForwardCacheRestore.
+  virtual void OnRequestAnimationFramesAfterBackForwardCacheRestoreInPage(
+      const mojom::BackForwardCacheTiming& timing) {}
+
   // Unlike other paint callbacks, OnFirstMeaningfulPaintInMainFrameDocument is
   // tracked per document, and is reported for the main frame document only.
   virtual void OnFirstMeaningfulPaintInMainFrameDocument(

components/page_load_metrics/browser/page_load_tracker.cc

@@ -141,6 +141,18 @@ void DispatchEventsAfterBackForwardCacheRestore(
                                                                i);
     }
 
+    auto request_animation_frames =
+        new_timings[i]
+            ->request_animation_frames_after_back_forward_cache_restore;
+    if (request_animation_frames.size() == 3 &&
+        (i >= last_timings.size() ||
+         last_timings[i]
+             ->request_animation_frames_after_back_forward_cache_restore
+             .empty())) {
+      observer->OnRequestAnimationFramesAfterBackForwardCacheRestoreInPage(
+          *new_timings[i]);
+    }
+
     auto first_input_delay =
         new_timings[i]->first_input_delay_after_back_forward_cache_restore;
     if (first_input_delay.has_value() &&

components/page_load_metrics/common/page_load_metrics.mojom

@@ -353,6 +353,10 @@ struct BackForwardCacheTiming {
   // is restored from the back-forward cache.
   mojo_base.mojom.TimeDelta first_paint_after_back_forward_cache_restore;
 
+  // Times on requestAnimationFrame when the page is restored from the back-
+  // forward cache.
+  array<mojo_base.mojom.TimeDelta> request_animation_frames_after_back_forward_cache_restore;
+
   // Queueing Time of the first click, tap, key press, cancellable touchstart,
   // or pointer down followed by a pointer up after the time when the page is
   // restored from the back-forward cache.

components/page_load_metrics/renderer/metrics_render_frame_observer.cc

@@ -528,6 +528,13 @@ MetricsRenderFrameObserver::Timing MetricsRenderFrameObserver::GetTiming()
             ->first_paint_after_back_forward_cache_restore =
             ClampDelta(first_paint, navigation_start);
       }
+      for (double raf : restore_timing.request_animation_frames) {
+        if (!raf)
+          break;
+        back_forward_cache_timing
+            ->request_animation_frames_after_back_forward_cache_restore
+            .push_back(ClampDelta(raf, navigation_start));
+      }
       if (first_input_delay.has_value()) {
         back_forward_cache_timing
             ->first_input_delay_after_back_forward_cache_restore =

third_party/blink/public/web/web_performance.h

@@ -47,9 +47,17 @@ class WindowPerformance;
 
 class WebPerformance {
  public:
+  // The count to record the times on requestAnimationFrame after the page is
+  // restored from the back-forward cache.
+  static constexpr int
+      kRequestAnimationFramesToRecordAfterBackForwardCacheRestore = 3;
+
   struct BackForwardCacheRestoreTiming {
     double navigation_start = 0;
     double first_paint = 0;
+    std::array<double,
+               kRequestAnimationFramesToRecordAfterBackForwardCacheRestore>
+        request_animation_frames = {};
     base::Optional<base::TimeDelta> first_input_delay;
   };
 

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

@@ -80,6 +80,11 @@ WebPerformance::BackForwardCacheRestore() const {
         MillisecondsToSeconds(restore_timings[i].navigation_start);
     timings[i].first_paint =
         MillisecondsToSeconds(restore_timings[i].first_paint);
+    for (size_t j = 0; j < restore_timings[i].request_animation_frames.size();
+         j++) {
+      timings[i].request_animation_frames[j] =
+          MillisecondsToSeconds(restore_timings[i].request_animation_frames[j]);
+    }
     timings[i].first_input_delay = restore_timings[i].first_input_delay;
   }
   return timings;

third_party/blink/renderer/core/paint/paint_timing.cc

@@ -10,6 +10,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/time/default_tick_clock.h"
 #include "third_party/blink/renderer/core/dom/document.h"
+#include "third_party/blink/renderer/core/dom/frame_request_callback_collection.h"
 #include "third_party/blink/renderer/core/frame/local_dom_window.h"
 #include "third_party/blink/renderer/core/frame/local_frame.h"
 #include "third_party/blink/renderer/core/frame/local_frame_view.h"
@@ -42,6 +43,47 @@ WindowPerformance* GetPerformanceInstance(LocalFrame* frame) {
 
 }  // namespace
 
+class RecodingTimeAfterBackForwardCacheRestoreFrameCallback
+    : public FrameCallback {
+ public:
+  RecodingTimeAfterBackForwardCacheRestoreFrameCallback(
+      PaintTiming* paint_timing,
+      size_t record_index)
+      : paint_timing_(paint_timing), record_index_(record_index) {}
+  ~RecodingTimeAfterBackForwardCacheRestoreFrameCallback() override = default;
+
+  void Invoke(double high_res_time_ms) override {
+    // Instead of |high_res_time_ms|, use PaintTiming's |clock_->NowTicks()| for
+    // consistency and testability.
+    paint_timing_->SetRequestAnimationFrameAfterBackForwardCacheRestore(
+        record_index_, count_);
+
+    count_++;
+    if (count_ ==
+        WebPerformance::
+            kRequestAnimationFramesToRecordAfterBackForwardCacheRestore) {
+      paint_timing_->NotifyPaintTimingChanged();
+      return;
+    }
+
+    if (auto* frame = paint_timing_->GetFrame()) {
+      if (auto* document = frame->GetDocument()) {
+        document->RequestAnimationFrame(this);
+      }
+    }
+  }
+
+  void Trace(Visitor* visitor) const override {
+    visitor->Trace(paint_timing_);
+    FrameCallback::Trace(visitor);
+  }
+
+ private:
+  Member<PaintTiming> paint_timing_;
+  const size_t record_index_;
+  size_t count_ = 0;
+};
+
 // static
 const char PaintTiming::kSupplementName[] = "PaintTiming";
 
@@ -334,6 +376,21 @@ void PaintTiming::SetFirstPaintAfterBackForwardCacheRestoreSwap(
   NotifyPaintTimingChanged();
 }
 
+void PaintTiming::SetRequestAnimationFrameAfterBackForwardCacheRestore(
+    size_t index,
+    size_t count) {
+  auto now = clock_->NowTicks();
+
+  // The elements are allocated when the page is restored from the cache.
+  DCHECK_LT(index,
+            request_animation_frames_after_back_forward_cache_restore_.size());
+  auto& current_rafs =
+      request_animation_frames_after_back_forward_cache_restore_[index];
+  DCHECK_LT(count, current_rafs.size());
+  DCHECK_EQ(current_rafs[count], base::TimeTicks());
+  current_rafs[count] = now;
+}
+
 void PaintTiming::ReportSwapResultHistogram(WebSwapResult result) {
   UMA_HISTOGRAM_ENUMERATION("PageLoad.Internal.Renderer.PaintTiming.SwapResult",
                             result);
@@ -343,9 +400,36 @@ void PaintTiming::OnRestoredFromBackForwardCache() {
   // Allocate the last element with 0, which indicates that the first paint
   // after this navigation doesn't happen yet.
   size_t index = first_paints_after_back_forward_cache_restore_swap_.size();
+  DCHECK_EQ(index,
+            request_animation_frames_after_back_forward_cache_restore_.size());
+
   first_paints_after_back_forward_cache_restore_swap_.push_back(
       base::TimeTicks());
   RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(index);
+
+  request_animation_frames_after_back_forward_cache_restore_.push_back(
+      RequestAnimationFrameTimesAfterBackForwardCacheRestore{});
+
+  LocalFrame* frame = GetFrame();
+  if (!frame->IsMainFrame()) {
+    return;
+  }
+
+  Document* document = frame->GetDocument();
+  DCHECK(document);
+
+  // Cancel if there is already a registered callback.
+  if (raf_after_bfcache_restore_measurement_callback_id_) {
+    document->CancelAnimationFrame(
+        raf_after_bfcache_restore_measurement_callback_id_);
+    raf_after_bfcache_restore_measurement_callback_id_ = 0;
+  }
+
+  raf_after_bfcache_restore_measurement_callback_id_ =
+      document->RequestAnimationFrame(
+          MakeGarbageCollected<
+              RecodingTimeAfterBackForwardCacheRestoreFrameCallback>(this,
+                                                                     index));
 }
 
 }  // namespace blink

third_party/blink/renderer/core/paint/paint_timing.h

@@ -7,6 +7,7 @@
 
 #include <memory>
 
+#include "third_party/blink/public/web/web_performance.h"
 #include "third_party/blink/public/web/web_swap_result.h"
 #include "third_party/blink/renderer/core/dom/document.h"
 #include "third_party/blink/renderer/core/paint/first_meaningful_paint_detector.h"
@@ -30,6 +31,10 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
   friend class FirstMeaningfulPaintDetector;
   using ReportTimeCallback =
       WTF::CrossThreadOnceFunction<void(WebSwapResult, base::TimeTicks)>;
+  using RequestAnimationFrameTimesAfterBackForwardCacheRestore = std::array<
+      base::TimeTicks,
+      WebPerformance::
+          kRequestAnimationFramesToRecordAfterBackForwardCacheRestore>;
 
  public:
   static const char kSupplementName[];
@@ -90,6 +95,11 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
     return first_paints_after_back_forward_cache_restore_swap_;
   }
 
+  WTF::Vector<RequestAnimationFrameTimesAfterBackForwardCacheRestore>
+  RequestAnimationFramesAfterBackForwardCacheRestore() const {
+    return request_animation_frames_after_back_forward_cache_restore_;
+  }
+
   // FirstContentfulPaint returns the first time that 'contentful' content was
   // painted. For instance, the first time that text or image content was
   // painted.
@@ -146,6 +156,8 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
   void Trace(Visitor*) const override;
 
  private:
+  friend class RecodingTimeAfterBackForwardCacheRestoreFrameCallback;
+
   LocalFrame* GetFrame() const;
   void NotifyPaintTimingChanged();
 
@@ -175,6 +187,8 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
   // index to avoid confusing the data from different navigations.
   void SetFirstPaintAfterBackForwardCacheRestoreSwap(base::TimeTicks stamp,
                                                      size_t index);
+  void SetRequestAnimationFrameAfterBackForwardCacheRestore(size_t index,
+                                                            size_t count);
 
   void RegisterNotifySwapTime(PaintEvent);
   void RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(
@@ -193,6 +207,8 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
   base::TimeTicks first_paint_swap_;
   WTF::Vector<base::TimeTicks>
       first_paints_after_back_forward_cache_restore_swap_;
+  WTF::Vector<RequestAnimationFrameTimesAfterBackForwardCacheRestore>
+      request_animation_frames_after_back_forward_cache_restore_;
   base::TimeTicks first_image_paint_;
   base::TimeTicks first_image_paint_swap_;
   base::TimeTicks first_contentful_paint_;
@@ -205,6 +221,10 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
 
   Member<FirstMeaningfulPaintDetector> fmp_detector_;
 
+  // The callback ID for requestAnimationFrame to record its time after the page
+  // is restored from the back-forward cache.
+  int raf_after_bfcache_restore_measurement_callback_id_ = 0;
+
   const base::TickClock* clock_;
 
   FRIEND_TEST_ALL_PREFIXES(FirstMeaningfulPaintDetectorTest, NoFirstPaint);

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

@@ -337,9 +337,16 @@ PerformanceTiming::BackForwardCacheRestore() const {
       load_timing->BackForwardCacheRestoreNavigationStarts();
   WTF::Vector<base::TimeTicks> first_paints =
       paint_timing->FirstPaintsAfterBackForwardCacheRestore();
+  WTF::Vector<std::array<
+      base::TimeTicks,
+      WebPerformance::
+          kRequestAnimationFramesToRecordAfterBackForwardCacheRestore>>
+      request_animation_frames =
+          paint_timing->RequestAnimationFramesAfterBackForwardCacheRestore();
   WTF::Vector<base::Optional<base::TimeDelta>> first_input_delays =
       interactive_detector->GetFirstInputDelaysAfterBackForwardCacheRestore();
   DCHECK_EQ(navigation_starts.size(), first_paints.size());
+  DCHECK_EQ(navigation_starts.size(), request_animation_frames.size());
   DCHECK_EQ(navigation_starts.size(), first_input_delays.size());
 
   WTF::Vector<BackForwardCacheRestoreTiming> restore_timings(
@@ -349,6 +356,10 @@ PerformanceTiming::BackForwardCacheRestore() const {
         MonotonicTimeToIntegerMilliseconds(navigation_starts[i]);
     restore_timings[i].first_paint =
         MonotonicTimeToIntegerMilliseconds(first_paints[i]);
+    for (size_t j = 0; j < request_animation_frames[i].size(); j++) {
+      restore_timings[i].request_animation_frames[j] =
+          MonotonicTimeToIntegerMilliseconds(request_animation_frames[i][j]);
+    }
     restore_timings[i].first_input_delay = first_input_delays[i];
   }
   return restore_timings;

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

@@ -32,6 +32,7 @@
 #define THIRD_PARTY_BLINK_RENDERER_CORE_TIMING_PERFORMANCE_TIMING_H_
 
 #include "base/time/time.h"
+#include "third_party/blink/public/web/web_performance.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"
@@ -61,6 +62,10 @@ class CORE_EXPORT PerformanceTiming final : public ScriptWrappable,
   struct BackForwardCacheRestoreTiming {
     uint64_t navigation_start;
     uint64_t first_paint;
+    std::array<uint64_t,
+               WebPerformance::
+                   kRequestAnimationFramesToRecordAfterBackForwardCacheRestore>
+        request_animation_frames;
     base::Optional<base::TimeDelta> first_input_delay;
   };
 

tools/metrics/histograms/histograms_xml/page/histograms.xml

@@ -1990,6 +1990,23 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram
+    name="PageLoad.PaintTiming.NavigationToFirstPaint.BFCachePolyfill{Count}"
+    units="ms" expires_after="2021-11-01">
+  <owner>altimin@chromium.org</owner>
+  <owner>bmcquade@chromium.org</owner>
+  <owner>hajimehoshi@chromium.org</owner>
+  <summary>
+    Meastures the time duration between the page restore from BFcache and the
+    {Count} requestAnimationFrame time.
+  </summary>
+  <token key="Count">
+    <variant name="First"/>
+    <variant name="Second"/>
+    <variant name="Third"/>
+  </token>
+</histogram>
+
 <histogram name="PageLoad.PaintTiming.NavigationToLargestContentfulPaint"
     units="ms" expires_after="2021-04-04">
   <owner>maxlg@chromium.org</owner>