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 {

[Charlie Harrison, 2017/05/26 19:31:34]

This feels a bit weird as a class. It's only allocated on the stack and used
very shortly. If you think the ergonomics of the class are much better than
straight functions I may suggest bringing it to a top-level class and allowing
it to be exposed + unit testable?

[Bryan McQuade, 2017/05/26 20:07:32]

Yeah, I wasn't planning to make this a helper class initially, but it made
exporting the did_merge_new_timing_value() bit ugly to instead return that as a
bool. In particular, I had to do things like:

  bool did_merge_new_timing_value = MaybeUpdateTimeDelta(&target_->first_paint,
navigation_start_offset,
                       new_paint_timing.first_paint);
  did_merge_new_timing_value = MaybeUpdateTimeDelta(&target_->first_text_paint,
navigation_start_offset,
                       new_paint_timing.first_text_paint) ||
did_merge_new_timing_value;
  did_merge_new_timing_value = MaybeUpdateTimeDelta(&target_->first_image_paint,
navigation_start_offset,
                       new_paint_timing.first_image_paint) ||
did_merge_new_timing_value;
  did_merge_new_timing_value =
MaybeUpdateTimeDelta(&target_->first_contentful_paint,
                       navigation_start_offset,
                       new_paint_timing.first_contentful_paint) ||
did_merge_new_timing_value;

which is both ugly and fragile, as if we forget one of these conditionals it
breaks.

By moving to a class, we can instead set the member did_merge_new_timing_value_
inside MaybeUpdateTimeDelta and it becomes much cleaner.

I think doing this in a helper class is pretty clearly preferable for this
reason. Let me know if you prefer to use the did_merge_new_timing_value = ... ||
did_merge_new_timing_value; approach above.

I'm skeptical that exposing this in the header and testing it improves test
coverage over our existing tests, and it pollutes the header with this
implementation detail. I can do it if you think it's important though.

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

Those reasons make sense to me.

I was thinking of moving it to a separate file wholesale. I don't feel strongly
about it though.

+ 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.
+    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() {
+  if (timer_->IsRunning()) {
+    timer_->Stop();

[Charlie Harrison, 2017/05/26 19:31:34]

It feels wrong that we need to explicitly stop the timer here (due to
DispatchTimingUpdates implementation). I've suggested a change in that method.

[Bryan McQuade, 2017/05/26 20:07:32]

Looking at your comment there, you suggested retaining a DCHECK, which I think
makes sense, but then that means we still need to stop the timer here. 

The motivation for calling Stop() here wasn't to interact nicely with
DispatchTimingUpdates() - rather, it's more explicit that we're cleaning up
resources & IMO more readable than assuming the timer is stopped when it goes
out of scope.

Note that we do the same thing in the PageTimingMetricsSender destructor:
PageTimingMetricsSender::~PageTimingMetricsSender() {
  if (timer_->IsRunning()) {
    timer_->Stop();
    SendNow();
  }
}

And we see this in other places in the codebase as well, e.g.
https://cs.chromium.org/chromium/src/ui/message_center/popup_timer.cc?l=21

+    DispatchTimingUpdates();

[Charlie Harrison, 2017/05/26 19:31:34]

Maybe user Timer::user_task to avoid duplicating the method?

[Bryan McQuade, 2017/05/26 20:07:32]

Need to circle back on this one - will look and see shortly.

[Bryan McQuade, 2017/05/26 21:51:32]

I look a look - it appears to not be possible to keep hold of the user_task. I
tried:

base::Closure user_task = timer_->user_task();
timer_->Stop();
user_task.Run();

but this blows up at runtime. the user_task() method returns a const ref so I'm
not even sure how the assignment is compiling, but it's clearly not working.

I could do:

  if (timer_->IsRunning()) {
    timer_->user_task().Run();
    timer_->Stop();
  }

but this feels wrong (reaching into timer internal state to force invoke the
timer) and it crashes, presumably for a similar reason (I suspect invoking Run()
on the returned const ref may cause an implicit copy, which compiles but doesn't
actually work at runtime).

So I left this as is.

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

Yeah I feel like this comment was piggybacking on the above one so the code
would look like:
if (timer_->IsRunning())
  timer_->user_task().Run()

Without needing to call Stop() on the timer since it's going out of scope. If
that crashes I guess it's not workable but it's surprising to me since we call
Run() on user_task() elsewhere.

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

My understanding is that it's safe to call Run() on the user_task() as long as
retain_user_task is true in the constructor, which is the case for a repeating
timer, but not a OneShotTimer which we're using. LMK if you find out otherwise -
happy to make changes.

+  }
+}
 
 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 {
+    DispatchTimingUpdates();
+  }
+}
+
 void PageLoadMetricsUpdateDispatcher::DispatchTimingUpdates() {
+  if (timer_->IsRunning())

[Charlie Harrison, 2017/05/26 19:31:34]

I would prefer if we could DCHECK(!timer_->IsRunning) here

[Bryan McQuade, 2017/05/26 20:07:32]

Done

+    return;
+
   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