Buffer cross frame paint timing updates.

chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc

Index: chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
diff --git a/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc b/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
index f5e4ec5fa3fa7f7dcb2b509d043f36ea34fb9144..3a3ef7278f2a879bf86d5289a6f6e4da08493d81 100644
--- a/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
+++ b/chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc
@@ -25,6 +25,10 @@ namespace internal {
 const char kPageLoadTimingStatus[] = "PageLoad.Internal.PageLoadTimingStatus";
 const char kPageLoadTimingDispatchStatus[] =
     "PageLoad.Internal.PageLoadTimingStatus.AtTimingCallbackDispatch";
+const char kHistogramOutOfOrderTiming[] =
+    "PageLoad.Internal.OutOfOrderInterFrameTiming";
+const char kHistogramOutOfOrderTimingBuffered[] =
+    "PageLoad.Internal.OutOfOrderInterFrameTiming.AfterBuffering";
 
 }  // namespace internal
 
@@ -200,10 +204,57 @@ internal::PageLoadTimingStatus IsValidPageLoadTiming(
   return internal::VALID;
 }
 
+// If the updated value has an earlier time than the current value, log so we
+// can keep track of how often this happens.
+void LogIfOutOfOrderTiming(const base::Optional<base::TimeDelta>& current,
+                           const base::Optional<base::TimeDelta>& update) {
+  if (!current || !update)
+    return;
+
+  if (update < current) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramOutOfOrderTimingBuffered,
+                        current.value() - update.value());
+  }
+}
+
+// PaintTimingMerger merges paint timing values received from different frames
+// together.
+class PaintTimingMerger {
+ public:
+  explicit PaintTimingMerger(mojom::PaintTiming* target) : target_(target) {}
+
+  // Merge paint timing values from |new_paint_timing| into the target
+  // PaintTiming.
+  void Merge(base::TimeDelta navigation_start_offset,
+             const mojom::PaintTiming& new_paint_timing,
+             bool is_main_frame);
+
+  // Whether we merged a new value, for a paint timing field we didn't
+  // previously have a value for in the target PaintTiming.
+  bool did_merge_new_timing_value() const {
+    return did_merge_new_timing_value_;
+  }
+
+ private:
+  void MaybeUpdateTimeDelta(
+      base::Optional<base::TimeDelta>* inout_existing_value,
+      base::TimeDelta navigation_start_offset,
+      const base::Optional<base::TimeDelta>& optional_candidate_new_value);
+
+  // The target PaintTiming we are merging values into.
+  mojom::PaintTiming* const target_;
+
+  // Whether we merged a new value, for a paint timing field we didn't
+  // previously have a value for in |target_|.
+  bool did_merge_new_timing_value_ = false;
+
+  DISALLOW_COPY_AND_ASSIGN(PaintTimingMerger);
+};
+
 // Updates *|inout_existing_value| with |optional_candidate_new_value|, if
 // either *|inout_existing_value| isn't set, or |optional_candidate_new_value| <
 // |inout_existing_value|.
-void MaybeUpdateTimeDelta(
+void PaintTimingMerger::MaybeUpdateTimeDelta(
     base::Optional<base::TimeDelta>* inout_existing_value,
     base::TimeDelta navigation_start_offset,
     const base::Optional<base::TimeDelta>& optional_candidate_new_value) {
@@ -228,13 +279,33 @@ void MaybeUpdateTimeDelta(
     // occasionally, as inter-frame updates can arrive out of order. Record a
     // histogram to track how frequently it happens, along with the magnitude
     // of the delta.
-    PAGE_LOAD_HISTOGRAM("PageLoad.Internal.OutOfOrderInterFrameTiming",
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramOutOfOrderTiming,
                         inout_existing_value->value() - candidate_new_value);
+  } else {
+    did_merge_new_timing_value_ = true;
   }
 
   *inout_existing_value = candidate_new_value;
 }
 
+void PaintTimingMerger::Merge(base::TimeDelta navigation_start_offset,
+                              const mojom::PaintTiming& new_paint_timing,
+                              bool is_main_frame) {
+  MaybeUpdateTimeDelta(&target_->first_paint, navigation_start_offset,
+                       new_paint_timing.first_paint);
+  MaybeUpdateTimeDelta(&target_->first_text_paint, navigation_start_offset,
+                       new_paint_timing.first_text_paint);
+  MaybeUpdateTimeDelta(&target_->first_image_paint, navigation_start_offset,
+                       new_paint_timing.first_image_paint);
+  MaybeUpdateTimeDelta(&target_->first_contentful_paint,
+                       navigation_start_offset,
+                       new_paint_timing.first_contentful_paint);
+  if (is_main_frame) {
+    // first meaningful paint is only tracked in the main frame.

[Charlie Harrison, 2017/05/30 14:49:07]

First

[Bryan McQuade, 2017/05/30 15:30:22]

done

+    target_->first_meaningful_paint = new_paint_timing.first_meaningful_paint;
+  }
+}
+
 }  // namespace
 
 PageLoadMetricsUpdateDispatcher::PageLoadMetricsUpdateDispatcher(
@@ -243,13 +314,24 @@ PageLoadMetricsUpdateDispatcher::PageLoadMetricsUpdateDispatcher(
     PageLoadMetricsEmbedderInterface* embedder_interface)
     : client_(client),
       embedder_interface_(embedder_interface),
+      timer_(embedder_interface->CreateTimer()),
       navigation_start_(navigation_handle->NavigationStart()),
       current_merged_page_timing_(CreatePageLoadTiming()),
       pending_merged_page_timing_(CreatePageLoadTiming()),
       main_frame_metadata_(mojom::PageLoadMetadata::New()),
       subframe_metadata_(mojom::PageLoadMetadata::New()) {}
 
-PageLoadMetricsUpdateDispatcher::~PageLoadMetricsUpdateDispatcher() {}
+PageLoadMetricsUpdateDispatcher::~PageLoadMetricsUpdateDispatcher() {
+  ShutDown();
+}
+
+void PageLoadMetricsUpdateDispatcher::ShutDown() {

[Charlie Harrison, 2017/05/30 14:49:07]

As mentioned earlier, if we just used
unique_ptr<PageLoadMetricsUpdateDispatcher> we wouldn't need this extra
Shutdown() logic and could just move to the destructor.

[Bryan McQuade, 2017/05/30 15:30:23]

My sense is these are two equivalent ways to accomplish the same thing, and in
some ways, having a ShutDown is preferable since it's more explicit. If shut
down code is important and needs to run at a certain time outside of the normal
destruction flow, my preference is to have an explicit shutdown method, which
makes it clearer than calling reset() (which is more commonly associated with
freeing up resources than with running important shutdown code).

[Charlie Harrison, 2017/05/30 16:33:15]

I hear you, and that argument makes sense. My preference is to use the
unique_ptr way so we never have a state where the object is accessible but in an
invalid state. Up to you.

+  if (timer_ && timer_->IsRunning()) {
+    timer_->Stop();
+    DispatchTimingUpdates();
+  }
+  timer_ = nullptr;
+}
 
 void PageLoadMetricsUpdateDispatcher::UpdateMetrics(
     content::RenderFrameHost* render_frame_host,
@@ -303,32 +385,11 @@ void PageLoadMetricsUpdateDispatcher::UpdateSubFrameTiming(
   client_->OnSubFrameTimingChanged(new_timing);
 
   base::TimeDelta navigation_start_offset = it->second;
-  MergePaintTiming(navigation_start_offset, *(new_timing.paint_timing),
-                   false /* is_main_frame */);
+  PaintTimingMerger merger(pending_merged_page_timing_->paint_timing.get());
+  merger.Merge(navigation_start_offset, *new_timing.paint_timing,
+               false /* is_main_frame */);
 
-  DispatchTimingUpdates();
-}
-
-void PageLoadMetricsUpdateDispatcher::MergePaintTiming(
-    base::TimeDelta navigation_start_offset,
-    const mojom::PaintTiming& new_paint_timing,
-    bool is_main_frame) {
-  MaybeUpdateTimeDelta(&pending_merged_page_timing_->paint_timing->first_paint,
-                       navigation_start_offset, new_paint_timing.first_paint);
-  MaybeUpdateTimeDelta(
-      &pending_merged_page_timing_->paint_timing->first_text_paint,
-      navigation_start_offset, new_paint_timing.first_text_paint);
-  MaybeUpdateTimeDelta(
-      &pending_merged_page_timing_->paint_timing->first_image_paint,
-      navigation_start_offset, new_paint_timing.first_image_paint);
-  MaybeUpdateTimeDelta(
-      &pending_merged_page_timing_->paint_timing->first_contentful_paint,
-      navigation_start_offset, new_paint_timing.first_contentful_paint);
-  if (is_main_frame) {
-    // first meaningful paint is only tracked in the main frame.
-    pending_merged_page_timing_->paint_timing->first_meaningful_paint =
-        new_paint_timing.first_meaningful_paint;
-  }
+  MaybeDispatchTimingUpdates(merger.did_merge_new_timing_value());
 }
 
 void PageLoadMetricsUpdateDispatcher::UpdateSubFrameMetadata(
@@ -374,10 +435,12 @@ void PageLoadMetricsUpdateDispatcher::UpdateMainFrameTiming(
   // observed |paint_timing|, which is tracked across all frames in the page.
   pending_merged_page_timing_ = new_timing.Clone();
   pending_merged_page_timing_->paint_timing = std::move(last_paint_timing);
-  MergePaintTiming(base::TimeDelta(), *new_timing.paint_timing,
-                   true /* is_main_frame */);
 
-  DispatchTimingUpdates();
+  PaintTimingMerger merger(pending_merged_page_timing_->paint_timing.get());
+  merger.Merge(base::TimeDelta(), *new_timing.paint_timing,
+               true /* is_main_frame */);
+
+  MaybeDispatchTimingUpdates(merger.did_merge_new_timing_value());
 }
 
 void PageLoadMetricsUpdateDispatcher::UpdateMainFrameMetadata(
@@ -398,7 +461,24 @@ void PageLoadMetricsUpdateDispatcher::UpdateMainFrameMetadata(
   client_->OnMainFrameMetadataChanged();
 }
 
+void PageLoadMetricsUpdateDispatcher::MaybeDispatchTimingUpdates(
+    bool did_merge_new_timing_value) {
+  // If we merged a new timing value, then we should buffer updates for
+  // |kBufferTimerDelayMillis|, to allow for any other out of order timings to
+  // arrive before we dispatch the minimum observed timings to observers.
+  if (did_merge_new_timing_value) {
+    timer_->Start(
+        FROM_HERE, base::TimeDelta::FromMilliseconds(kBufferTimerDelayMillis),
+        base::Bind(&PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates,
+                   base::Unretained(this)));
+  } else if (!timer_->IsRunning()) {
+    DispatchTimingUpdates();
+  }
+}
+
 void PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates() {
+  DCHECK(!timer_->IsRunning());
+
   if (pending_merged_page_timing_->paint_timing->first_paint) {
     if (!pending_merged_page_timing_->parse_timing->parse_start ||
         !pending_merged_page_timing_->document_timing->first_layout) {
@@ -418,6 +498,19 @@ void PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates() {
 
   if (current_merged_page_timing_->Equals(*pending_merged_page_timing_))
     return;
+
+  LogIfOutOfOrderTiming(current_merged_page_timing_->paint_timing->first_paint,
+                        pending_merged_page_timing_->paint_timing->first_paint);
+  LogIfOutOfOrderTiming(
+      current_merged_page_timing_->paint_timing->first_text_paint,
+      pending_merged_page_timing_->paint_timing->first_text_paint);
+  LogIfOutOfOrderTiming(
+      current_merged_page_timing_->paint_timing->first_image_paint,
+      pending_merged_page_timing_->paint_timing->first_image_paint);
+  LogIfOutOfOrderTiming(
+      current_merged_page_timing_->paint_timing->first_contentful_paint,
+      pending_merged_page_timing_->paint_timing->first_contentful_paint);
+
   current_merged_page_timing_ = pending_merged_page_timing_->Clone();
 
   internal::PageLoadTimingStatus status =