Buffer timing callbacks until timing state converges.

chrome/browser/page_load_metrics/page_load_tracker.cc

 // Copyright 2016 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 "chrome/browser/page_load_metrics/page_load_tracker.h"
 
 #include <algorithm>
 #include <ostream>
 #include <string>
 #include <utility>
@@ skipping 45 matching lines @@
 const char kClientRedirectFirstPaintToNavigation[] =
     "PageLoad.Internal.ClientRedirect.FirstPaintToNavigation";
 const char kClientRedirectWithoutPaint[] =
     "PageLoad.Internal.ClientRedirect.NavigationWithoutPaint";
 const char kPageLoadCompletedAfterAppBackground[] =
     "PageLoad.Internal.PageLoadCompleted.AfterAppBackground";
 const char kPageLoadStartedInForeground[] =
     "PageLoad.Internal.NavigationStartedInForeground";
 const char kPageLoadPrerender[] = "PageLoad.Internal.Prerender";
 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus";
+const char kPageLoadTimingDispatchStatus[] =
+    "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch";
 
 }  // namespace internal
 
 void RecordInternalError(InternalErrorLoadEvent event) {
   UMA_HISTOGRAM_ENUMERATION(internal::kErrorEvents, event, ERR_LAST_ENTRY);
 }
 
 // TODO(csharrison): Add a case for client side redirects, which is what JS
 // initiated window.location / window.history navigations get set to.
 PageEndReason EndReasonForPageTransition(ui::PageTransition transition) {
@@ skipping 559 matching lines @@
     const PageLoadMetadata& new_metadata) {
   UpdateSubFrameMetadata(new_metadata);
   const auto it = subframe_navigation_start_offset_.find(
       render_frame_host->GetFrameTreeNodeId());
   if (it == subframe_navigation_start_offset_.end()) {
     // We received timing information for an untracked load. Ignore it.
     return;
   }
 
   base::TimeDelta navigation_start_offset = it->second;
-  const PageLoadTiming last_timing = merged_page_timing_;
   MergePaintTiming(navigation_start_offset, new_timing.paint_timing,
                    false /* is_main_frame */);
 
-  if (last_timing == merged_page_timing_)
-    return;
-
-  const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
-  for (const auto& observer : observers_) {
-    DispatchObserverTimingCallbacks(observer.get(), last_timing,
-                                    merged_page_timing_, main_frame_metadata_,
-                                    info);
-  }
+  DispatchTimingUpdates();
 }
 
 void PageLoadTracker::MergePaintTiming(
     base::TimeDelta navigation_start_offset,
     const page_load_metrics::PaintTiming& new_paint_timing,
     bool is_main_frame) {
   MaybeUpdateTimeDelta(&merged_page_timing_.paint_timing.first_paint,
                        navigation_start_offset, new_paint_timing.first_paint);
   MaybeUpdateTimeDelta(&merged_page_timing_.paint_timing.first_text_paint,
                        navigation_start_offset,
@@ skipping 58 matching lines @@
   }
 
   DCHECK(did_commit_);  // OnCommit() must be called first.
   // There are some subtle ordering constraints here. GetPageLoadMetricsInfo()
   // must be called before DispatchObserverTimingCallbacks, but its
   // implementation depends on the state of main_frame_metadata_, so we need
   // to update main_frame_metadata_ before calling GetPageLoadMetricsInfo.
   // Thus, we make a copy of timing here, update timing_ and
   // main_frame_metadata_, and then proceed to dispatch the observer timing
   // callbacks.
-  const PageLoadTiming last_timing = merged_page_timing_;
+  const PaintTiming last_paint_timing = merged_page_timing_.paint_timing;
 
   // Update the merged_page_timing_, making sure to merge the previously
   // observed |paint_timing|, which is tracked across all frames in the page.
   merged_page_timing_ = new_timing;
-  merged_page_timing_.paint_timing = last_timing.paint_timing;
+  merged_page_timing_.paint_timing = last_paint_timing;
   MergePaintTiming(base::TimeDelta(), new_timing.paint_timing,
                    true /* is_main_frame */);
 
-  const PageLoadMetadata last_metadata = main_frame_metadata_;
   main_frame_metadata_ = new_metadata;
+
+  DispatchTimingUpdates();
+}
+
+void PageLoadTracker::DispatchTimingUpdates() {
+  if (last_dispatched_merged_page_timing_ == merged_page_timing_ &&
+      last_dispatched_main_frame_metadata_ == main_frame_metadata_) {
+    return;
+  }
+
+  if (merged_page_timing_.paint_timing.first_paint) {
+    if (!merged_page_timing_.parse_timing.parse_start ||
+        !merged_page_timing_.document_timing.first_layout) {
+      // When merging paint events across frames, we can sometimes encounter
+      // cases where we've received a first paint event for a child frame before
+      // receiving required earlier events in the main frame, due to buffering
+      // in the render process which results in out of order delivery. For
+      // example, we may receive a notification for a first paint in a child
+      // frame before we've received a notification for parse start or first
+      // layout in the main frame. In these cases, we delay sending timing
+      // updates until we've received all expected events (e.g. wait to receive
+      // a parse or layout event before dispatching a paint event), so observers
+      // can make assumptions about ordering of these events in their callbacks.
+      return;
+    }
+  }
+
+  internal::PageLoadTimingStatus status =
+      IsValidPageLoadTiming(merged_page_timing_);
+  UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status,
+                            internal::LAST_PAGE_LOAD_TIMING_STATUS);
+
   const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
   for (const auto& observer : observers_) {
-    DispatchObserverTimingCallbacks(observer.get(), last_timing,
-                                    merged_page_timing_, last_metadata, info);
+    DispatchObserverTimingCallbacks(
+        observer.get(), last_dispatched_merged_page_timing_,

[jkarlin, 2017/05/16 16:23:11]

Do you really want to dispatch the last observed timings? I figured you'd want
to dispatch the new ones here.

[Bryan McQuade, 2017/05/16 16:33:48]

DispatchObserverTimingCallbacks takes both the old and new timing so it can diff
them and only dispatch callbacks for values that changed. There should be no
behavior change here (see in the old code that we passed 'last_timing' in this
param).

[jkarlin, 2017/05/16 17:07:14]

Completely missed that merged_paint_timing_ was going through as well. Looks
good.

+        merged_page_timing_, last_dispatched_main_frame_metadata_, info);
   }
+  last_dispatched_merged_page_timing_ = merged_page_timing_;
+  last_dispatched_main_frame_metadata_ = main_frame_metadata_;
 }
 
 void PageLoadTracker::OnStartedResource(
     const ExtraRequestStartInfo& extra_request_start_info) {
   for (const auto& observer : observers_) {
     observer->OnStartedResource(extra_request_start_info);
   }
 }
 
 void PageLoadTracker::OnLoadedResource(
@@ skipping 174 matching lines @@
     observer->MediaStartedPlaying(video_type, is_in_main_frame);
 }
 
 void PageLoadTracker::OnNavigationDelayComplete(base::TimeDelta scheduled_delay,
                                                 base::TimeDelta actual_delay) {
   for (const auto& observer : observers_)
     observer->OnNavigationDelayComplete(scheduled_delay, actual_delay);
 }
 
 }  // namespace page_load_metrics