Buffer cross frame paint timing updates.

chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.cc

 // Copyright 2017 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_metrics_update_dispatcher.h"
 
 #include <ostream>
 #include <utility>
 
 #include "base/logging.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/optional.h"
 #include "chrome/browser/page_load_metrics/browser_page_track_decider.h"
 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.h"
 #include "chrome/browser/page_load_metrics/page_load_metrics_util.h"
 #include "chrome/browser/page_load_metrics/page_load_tracker.h"
 #include "chrome/common/page_load_metrics/page_load_metrics_constants.h"
 #include "content/public/browser/navigation_handle.h"
 #include "content/public/browser/render_frame_host.h"
 
 namespace page_load_metrics {
 
 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
 
 namespace {
 
 // Helper to allow use of Optional<> values in LOG() messages.
 std::ostream& operator<<(std::ostream& os,
                          const base::Optional<base::TimeDelta>& opt) {
   if (opt)
     os << opt.value();
@@ skipping 155 matching lines @@
                      timing.paint_timing->first_meaningful_paint)) {
     LOG(ERROR) << "Invalid first_paint " << timing.paint_timing->first_paint
                << " for first_meaningful_paint "
                << timing.paint_timing->first_meaningful_paint;
     return internal::INVALID_ORDER_FIRST_PAINT_FIRST_MEANINGFUL_PAINT;
   }
 
   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) {
   // If we don't get a new value, there's nothing to do
   if (!optional_candidate_new_value)
     return;
 
   // optional_candidate_new_value is relative to navigation start in its
   // frame. We need to adjust it to be relative to navigation start in the main
   // frame, so offset it by navigation_start_offset.
   base::TimeDelta candidate_new_value =
       navigation_start_offset + optional_candidate_new_value.value();
 
   if (*inout_existing_value) {
     // If we have a new value, but it is after the existing value, then keep the
     // existing value.
     if (*inout_existing_value <= candidate_new_value)
       return;
 
     // We received a new timing event, but with a timestamp before the timestamp
     // of a timing update we had received previously. We expect this to happen
     // 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(
     PageLoadMetricsUpdateDispatcher::Client* client,
     content::NavigationHandle* navigation_handle,
     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,
     const mojom::PageLoadTiming& new_timing,
     const mojom::PageLoadMetadata& new_metadata) {
   if (render_frame_host->GetParent() == nullptr) {
     UpdateMainFrameMetadata(new_metadata);
     UpdateMainFrameTiming(new_timing);
   } else {
     UpdateSubFrameMetadata(new_metadata);
@@ skipping 33 matching lines @@
   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;
   }
 
   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(
     const mojom::PageLoadMetadata& subframe_metadata) {
   // Merge the subframe loading behavior flags with any we've already observed,
   // possibly from other subframes.
   const int last_subframe_loading_behavior_flags =
       subframe_metadata_->behavior_flags;
   subframe_metadata_->behavior_flags |= subframe_metadata.behavior_flags;
   if (last_subframe_loading_behavior_flags ==
@@ skipping 25 matching lines @@
     RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING);
     return;
   }
 
   mojom::PaintTimingPtr last_paint_timing =
       std::move(pending_merged_page_timing_->paint_timing);
   // Update the pending_merged_page_timing_, making sure to merge the previously
   // 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(
     const mojom::PageLoadMetadata& new_metadata) {
   if (main_frame_metadata_->Equals(new_metadata))
     return;
 
   // Ensure flags sent previously are still present in the new metadata fields.
   const bool valid_behavior_descendent =
       (main_frame_metadata_->behavior_flags & new_metadata.behavior_flags) ==
       main_frame_metadata_->behavior_flags;
   if (!valid_behavior_descendent) {
     RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_BEHAVIOR_DESCENDENT);
     return;
   }
 
   main_frame_metadata_ = new_metadata.Clone();
   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) {
       // 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;
     }
   }
 
   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 =
       IsValidPageLoadTiming(*pending_merged_page_timing_);
   UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingDispatchStatus, status,
                             internal::LAST_PAGE_LOAD_TIMING_STATUS);
 
   client_->OnTimingChanged();
 }
 
 }  // namespace page_load_metrics