BackForwardCache: Fix PaintTimings to record bfcache timings correctly

SetFirstPaintAfterBackForwardCacheRestoreSwap is called once when
OnRestoredFromBackForwardCache is called once, by registering the
callback.

When OnRestoredFromBackForwardCache was called twice very quickly,
two SetFirstPaintAfterBackForwardCacheRestoreSwap might try to set the
same end of the timing vector, which was wrong update.

This CL fixes this issue by specifying an index at the callback closure,
instead of always updating the end of the timing vector.

Bug: 1099395
Change-Id: Ic56d2c600d5f08cd7a71e4c03ac84a82a6925115
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2346690
Commit-Queue: Hajime Hoshi <hajimehoshi@chromium.org>
Reviewed-by: Alexander Timin <altimin@chromium.org>
Reviewed-by: Nicolás Peña Moreno <npm@chromium.org>
Reviewed-by: Kentaro Hara <haraken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#797606}

content/browser/back_forward_cache_browsertest.cc

@@ -710,9 +710,8 @@ IN_PROC_BROWSER_TEST_F(BackForwardCacheBrowserTest, BasicDocumentInitiated) {
 }
 
 // Navigate from back and forward repeatedly.
-// TODO(https://crbug.com/1099395): flaky.
 IN_PROC_BROWSER_TEST_F(BackForwardCacheBrowserTest,
-                       DISABLED_NavigateBackForwardRepeatedly) {
+                       NavigateBackForwardRepeatedly) {
   ASSERT_TRUE(embedded_test_server()->Start());
   GURL url_a(embedded_test_server()->GetURL("a.com", "/title1.html"));
   GURL url_b(embedded_test_server()->GetURL("b.com", "/title1.html"));

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

@@ -11,7 +11,6 @@ namespace blink {
 // SwapPromise swap times for.
 enum class PaintEvent {
   kFirstPaint,
-  kFirstPaintAfterBackForwardCacheRestore,
   kFirstContentfulPaint,
   kProvisionalFirstMeaningfulPaint,
   kFirstImagePaint,

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

@@ -211,6 +211,13 @@ void PaintTiming::RegisterNotifySwapTime(PaintEvent event) {
                           WrapCrossThreadWeakPersistent(this), event));
 }
 
+void PaintTiming::RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(
+    size_t index) {
+  RegisterNotifySwapTime(CrossThreadBindOnce(
+      &PaintTiming::ReportFirstPaintAfterBackForwardCacheRestoreSwapTime,
+      WrapCrossThreadWeakPersistent(this), index));
+}
+
 void PaintTiming::RegisterNotifySwapTime(ReportTimeCallback callback) {
   // ReportSwapTime will queue a swap-promise, the callback is called when the
   // compositor submission of the current render frame completes or fails to
@@ -242,9 +249,6 @@ void PaintTiming::ReportSwapTime(PaintEvent event,
     case PaintEvent::kFirstPaint:
       SetFirstPaintSwap(timestamp);
       return;
-    case PaintEvent::kFirstPaintAfterBackForwardCacheRestore:
-      SetFirstPaintAfterBackForwardCacheRestoreSwap(timestamp);
-      return;
     case PaintEvent::kFirstContentfulPaint:
       SetFirstContentfulPaintSwap(timestamp);
       return;
@@ -259,6 +263,15 @@ void PaintTiming::ReportSwapTime(PaintEvent event,
   }
 }
 
+void PaintTiming::ReportFirstPaintAfterBackForwardCacheRestoreSwapTime(
+    size_t index,
+    WebSwapResult result,
+    base::TimeTicks timestamp) {
+  DCHECK(IsMainThread());
+  ReportSwapResultHistogram(result);
+  SetFirstPaintAfterBackForwardCacheRestoreSwap(timestamp, index);
+}
+
 void PaintTiming::SetFirstPaintSwap(base::TimeTicks stamp) {
   DCHECK(first_paint_swap_.is_null());
   first_paint_swap_ = stamp;
@@ -306,12 +319,12 @@ void PaintTiming::SetFirstImagePaintSwap(base::TimeTicks stamp) {
 }
 
 void PaintTiming::SetFirstPaintAfterBackForwardCacheRestoreSwap(
-    base::TimeTicks stamp) {
-  // The last element is already allocated when the page is restored from the
-  // cache.
-  DCHECK(!first_paints_after_back_forward_cache_restore_swap_.IsEmpty());
-  DCHECK(first_paints_after_back_forward_cache_restore_swap_.back().is_null());
-  first_paints_after_back_forward_cache_restore_swap_.back() = stamp;
+    base::TimeTicks stamp,
+    size_t index) {
+  // The elements are allocated when the page is restored from the cache.
+  DCHECK_GE(first_paints_after_back_forward_cache_restore_swap_.size(), index);
+  DCHECK(first_paints_after_back_forward_cache_restore_swap_[index].is_null());
+  first_paints_after_back_forward_cache_restore_swap_[index] = stamp;
   NotifyPaintTimingChanged();
 }
 
@@ -326,9 +339,10 @@ void PaintTiming::ReportSwapResultHistogram(WebSwapResult result) {
 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();
   first_paints_after_back_forward_cache_restore_swap_.push_back(
       base::TimeTicks());
-  RegisterNotifySwapTime(PaintEvent::kFirstPaintAfterBackForwardCacheRestore);
+  RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(index);
 }
 
 }  // namespace blink

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

@@ -130,6 +130,10 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
 
   void RegisterNotifySwapTime(ReportTimeCallback);
   void ReportSwapTime(PaintEvent, WebSwapResult, base::TimeTicks timestamp);
+  void ReportFirstPaintAfterBackForwardCacheRestoreSwapTime(
+      size_t index,
+      WebSwapResult,
+      base::TimeTicks timestamp);
 
   void ReportSwapResultHistogram(WebSwapResult);
 
@@ -165,9 +169,15 @@ class CORE_EXPORT PaintTiming final : public GarbageCollected<PaintTiming>,
   void SetFirstContentfulPaintSwap(base::TimeTicks stamp);
   void SetFirstImagePaintSwap(base::TimeTicks stamp);
 
-  void SetFirstPaintAfterBackForwardCacheRestoreSwap(base::TimeTicks stamp);
+  // When quickly navigating back and forward between the pages in the cache
+  // paint events might race with navigations. Pass explicit bfcache restore
+  // index to avoid confusing the data from different navigations.
+  void SetFirstPaintAfterBackForwardCacheRestoreSwap(base::TimeTicks stamp,
+                                                     size_t index);
 
   void RegisterNotifySwapTime(PaintEvent);
+  void RegisterNotifyFirstPaintAfterBackForwardCacheRestoreSwapTime(
+      size_t index);
 
   base::TimeTicks FirstPaintRendered() const { return first_paint_; }