Report page load timing information for child frames.

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>
 
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/histogram_macros.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/prerender/prerender_contents.h"
 #include "chrome/common/page_load_metrics/page_load_timing.h"
 #include "content/public/browser/navigation_details.h"
 #include "content/public/browser/navigation_handle.h"
+#include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/web_contents.h"
 #include "content/public/browser/web_contents_observer.h"
 #include "content/public/common/browser_side_navigation_policy.h"
 #include "ui/base/page_transition_types.h"
 
 // This macro invokes the specified method on each observer, passing the
 // variable length arguments as the method's arguments, and removes the observer
 // from the list of observers if the given method returns STOP_OBSERVING.
 #define INVOKE_AND_PRUNE_OBSERVERS(observers, Method, ...)    \
   for (auto it = observers.begin(); it != observers.end();) { \
@@ skipping 67 matching lines @@
   // HasUserGesture() set to true. In the meantime, we consider all
   // browser-initiated navigations to be user initiated.
   //
   // TODO(crbug.com/637345): Some browser-initiated navigations incorrectly
   // report that they are renderer-initiated. We will currently report that
   // these navigations are not user initiated, when in fact they are user
   // initiated.
   return handle->HasUserGesture() || !handle->IsRendererInitiated();
 }
 
+content::RenderFrameHost* GetMainFrame(content::RenderFrameHost* rfh) {
+  // Don't use rfh->GetRenderViewHost()->GetMainFrame() here because
+  // RenderViewHost is being deprecated and because in OOPIF,
+  // RenderViewHost::GetMainFrame() returns nullptr for child frames hosted in a
+  // different process from the main frame.
+  while (rfh->GetParent() != nullptr)
+    rfh = rfh->GetParent();
+  return rfh;
+}
+
 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();
   else
     os << "(unset)";
   return os;
@@ skipping 145 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;
 }
 
+// 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(
+    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",
+                        inout_existing_value->value() - candidate_new_value);
+  }
+
+  *inout_existing_value = candidate_new_value;
+}
+
 void RecordAppBackgroundPageLoadCompleted(bool completed_after_background) {
   UMA_HISTOGRAM_BOOLEAN(internal::kPageLoadCompletedAfterAppBackground,
                         completed_after_background);
 }
 
 void DispatchObserverTimingCallbacks(PageLoadMetricsObserver* observer,
                                      const PageLoadTiming& last_timing,
                                      const PageLoadTiming& new_timing,
                                      const PageLoadMetadata& last_metadata,
                                      const PageLoadExtraInfo& extra_info) {
   if (extra_info.main_frame_metadata.behavior_flags !=
       last_metadata.behavior_flags)
     observer->OnLoadingBehaviorObserved(extra_info);
   if (last_timing != new_timing)
     observer->OnTimingUpdate(new_timing, extra_info);
   if (new_timing.document_timing.dom_content_loaded_event_start &&
       !last_timing.document_timing.dom_content_loaded_event_start)
     observer->OnDomContentLoadedEventStart(new_timing, extra_info);
   if (new_timing.document_timing.load_event_start &&
       !last_timing.document_timing.load_event_start)
     observer->OnLoadEventStart(new_timing, extra_info);
   if (new_timing.document_timing.first_layout &&
       !last_timing.document_timing.first_layout)
     observer->OnFirstLayout(new_timing, extra_info);
   if (new_timing.paint_timing.first_paint &&
       !last_timing.paint_timing.first_paint)
-    observer->OnFirstPaint(new_timing, extra_info);
+    observer->OnFirstPaintInPage(new_timing, extra_info);
   if (new_timing.paint_timing.first_text_paint &&
       !last_timing.paint_timing.first_text_paint)
-    observer->OnFirstTextPaint(new_timing, extra_info);
+    observer->OnFirstTextPaintInPage(new_timing, extra_info);
   if (new_timing.paint_timing.first_image_paint &&
       !last_timing.paint_timing.first_image_paint)
-    observer->OnFirstImagePaint(new_timing, extra_info);
+    observer->OnFirstImagePaintInPage(new_timing, extra_info);
   if (new_timing.paint_timing.first_contentful_paint &&
       !last_timing.paint_timing.first_contentful_paint)
-    observer->OnFirstContentfulPaint(new_timing, extra_info);
+    observer->OnFirstContentfulPaintInPage(new_timing, extra_info);
   if (new_timing.paint_timing.first_meaningful_paint &&
       !last_timing.paint_timing.first_meaningful_paint)
-    observer->OnFirstMeaningfulPaint(new_timing, extra_info);
+    observer->OnFirstMeaningfulPaintInMainFrameDocument(new_timing, extra_info);
   if (new_timing.parse_timing.parse_start &&
       !last_timing.parse_timing.parse_start)
     observer->OnParseStart(new_timing, extra_info);
   if (new_timing.parse_timing.parse_stop &&
       !last_timing.parse_timing.parse_stop)
     observer->OnParseStop(new_timing, extra_info);
 }
 
 }  // namespace
 
@@ skipping 54 matching lines @@
     if (!failed_provisional_load_info_)
       RecordInternalError(ERR_NO_COMMIT_OR_FAILED_PROVISIONAL_LOAD);
 
     // Don't include any aborts that resulted in a new navigation, as the chain
     // length will be included in the aborter PageLoadTracker.
     if (page_end_reason_ != END_RELOAD &&
         page_end_reason_ != END_FORWARD_BACK &&
         page_end_reason_ != END_NEW_NAVIGATION) {
       LogAbortChainHistograms(nullptr);
     }
-  } else if (timing_.IsEmpty()) {
+  } else if (merged_page_timing_.IsEmpty()) {
     RecordInternalError(ERR_NO_IPCS_RECEIVED);
   }
 
   const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
   for (const auto& observer : observers_) {
     if (failed_provisional_load_info_) {
       observer->OnFailedProvisionalLoad(*failed_provisional_load_info_, info);
     } else if (did_commit_) {
-      observer->OnComplete(timing_, info);
+      observer->OnComplete(merged_page_timing_, info);
     }
   }
 }
 
 void PageLoadTracker::LogAbortChainHistograms(
     content::NavigationHandle* final_navigation) {
   if (aborted_chain_size_ == 0)
     return;
   // Note that this could be broken out by this navigation's abort type, if more
   // granularity is needed. Add one to the chain size to count the current
@@ skipping 46 matching lines @@
   // Only log the first time we background in a given page load.
   if (background_time_.is_null()) {
     // Make sure we either started in the foreground and haven't been
     // foregrounded yet, or started in the background and have already been
     // foregrounded.
     DCHECK_EQ(started_in_foreground_, foreground_time_.is_null());
     background_time_ = base::TimeTicks::Now();
     ClampBrowserTimestampIfInterProcessTimeTickSkew(&background_time_);
   }
   const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
-  INVOKE_AND_PRUNE_OBSERVERS(observers_, OnHidden, timing_, info);
+  INVOKE_AND_PRUNE_OBSERVERS(observers_, OnHidden, merged_page_timing_, info);
 }
 
 void PageLoadTracker::WebContentsShown() {
   // Only log the first time we foreground in a given page load.
   if (foreground_time_.is_null()) {
     // Make sure we either started in the background and haven't been
     // backgrounded yet, or started in the foreground and have already been
     // backgrounded.
     DCHECK_NE(started_in_foreground_, background_time_.is_null());
     foreground_time_ = base::TimeTicks::Now();
@@ skipping 31 matching lines @@
       navigation_handle->GetWebContents()->GetContentsMimeType());
 
   INVOKE_AND_PRUNE_OBSERVERS(observers_, OnCommit, navigation_handle);
   LogAbortChainHistograms(navigation_handle);
 }
 
 void PageLoadTracker::DidFinishSubFrameNavigation(
     content::NavigationHandle* navigation_handle) {
   INVOKE_AND_PRUNE_OBSERVERS(observers_, OnDidFinishSubFrameNavigation,
                              navigation_handle);
+
+  if (!navigation_handle->HasCommitted())
+    return;
+
+  // We have a new committed navigation, so discard information about the
+  // previously committed navigation.
+  child_frame_navigation_start_offset_.erase(
+      navigation_handle->GetFrameTreeNodeId());
+
+  if (GetMainFrame(navigation_handle->GetRenderFrameHost()) !=
+      navigation_handle->GetWebContents()->GetMainFrame()) {
+    // Ignore navigations for a main frame that was navigated away from.
+    return;
+  }
+
+  BrowserPageTrackDecider decider(embedder_interface_,
+                                  navigation_handle->GetWebContents(),
+                                  navigation_handle);
+  if (!decider.ShouldTrack())
+    return;
+
+  if (navigation_start_ > navigation_handle->NavigationStart()) {
+    RecordInternalError(ERR_SUBFRAME_NAVIGATION_START_BEFORE_MAIN_FRAME);
+    return;
+  }
+  base::TimeDelta navigation_delta =
+      navigation_handle->NavigationStart() - navigation_start_;
+  child_frame_navigation_start_offset_.insert(std::make_pair(
+      navigation_handle->GetFrameTreeNodeId(), navigation_delta));
 }
 
 void PageLoadTracker::FailedProvisionalLoad(
     content::NavigationHandle* navigation_handle,
     base::TimeTicks failed_load_time) {
   DCHECK(!failed_provisional_load_info_);
   failed_provisional_load_info_.reset(new FailedProvisionalLoadInfo(
       failed_load_time - navigation_handle->NavigationStart(),
       navigation_handle->GetNetErrorCode()));
 }
@@ skipping 11 matching lines @@
 }
 
 void PageLoadTracker::FlushMetricsOnAppEnterBackground() {
   if (!app_entered_background_) {
     RecordAppBackgroundPageLoadCompleted(false);
     app_entered_background_ = true;
   }
 
   const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
   INVOKE_AND_PRUNE_OBSERVERS(observers_, FlushMetricsOnAppEnterBackground,
-                             timing_, info);
+                             merged_page_timing_, info);
 }
 
 void PageLoadTracker::NotifyClientRedirectTo(
     const PageLoadTracker& destination) {
-  if (timing_.paint_timing.first_paint) {
+  if (merged_page_timing_.paint_timing.first_paint) {
     base::TimeTicks first_paint_time =
-        navigation_start() + timing_.paint_timing.first_paint.value();
+        navigation_start() +
+        merged_page_timing_.paint_timing.first_paint.value();
     base::TimeDelta first_paint_to_navigation;
     if (destination.navigation_start() > first_paint_time)
       first_paint_to_navigation =
           destination.navigation_start() - first_paint_time;
     PAGE_LOAD_HISTOGRAM(internal::kClientRedirectFirstPaintToNavigation,
                         first_paint_to_navigation);
   } else {
     UMA_HISTOGRAM_BOOLEAN(internal::kClientRedirectWithoutPaint, true);
   }
 }
 
-void PageLoadTracker::UpdateChildFrameMetadata(
+void PageLoadTracker::UpdateSubFrameTiming(
+    content::RenderFrameHost* render_frame_host,
+    const PageLoadTiming& new_timing,
+    const PageLoadMetadata& new_metadata) {
+  UpdateSubFrameMetadata(new_metadata);
+  const auto it = child_frame_navigation_start_offset_.find(
+      render_frame_host->GetFrameTreeNodeId());
+  if (it == child_frame_navigation_start_offset_.end()) {
+    // We received timing information for an untracked load. Ignore it.
+    RecordInternalError(ERR_SUBFRAME_IPC_WITH_NO_RELEVANT_LOAD);
+    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 */);
+
+  const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
+  for (const auto& observer : observers_) {
+    observer->OnSubFrameTimingUpdate(render_frame_host->GetFrameTreeNodeId(),
+                                     navigation_start_offset, new_timing,
+                                     new_metadata, info);
+    DispatchObserverTimingCallbacks(observer.get(), last_timing,

[jkarlin, 2017/05/10 16:55:28]

It's potentially expensive to call all the observers. Do we want to call them if
nothing has changed in merged_page_timing_?

[Bryan McQuade, 2017/05/10 18:06:15]

done

+                                    merged_page_timing_, main_frame_metadata_,
+                                    info);
+  }
+}
+
+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,
+                       new_paint_timing.first_text_paint);
+  MaybeUpdateTimeDelta(&merged_page_timing_.paint_timing.first_image_paint,
+                       navigation_start_offset,
+                       new_paint_timing.first_image_paint);
+  MaybeUpdateTimeDelta(&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.
+    merged_page_timing_.paint_timing.first_meaningful_paint =
+        new_paint_timing.first_meaningful_paint;
+  }
+}
+
+void PageLoadTracker::UpdateSubFrameMetadata(
     const PageLoadMetadata& child_metadata) {
   // Merge the child loading behavior flags with any we've already observed,
   // possibly from other child frames.
   const int last_child_loading_behavior_flags =
       child_frame_metadata_.behavior_flags;
   child_frame_metadata_.behavior_flags |= child_metadata.behavior_flags;
   if (last_child_loading_behavior_flags == child_frame_metadata_.behavior_flags)
     return;
 
   PageLoadExtraInfo extra_info(ComputePageLoadExtraInfo());
   for (const auto& observer : observers_) {
     observer->OnLoadingBehaviorObserved(extra_info);
   }
 }
 
 void PageLoadTracker::UpdateTiming(const PageLoadTiming& new_timing,
                                    const PageLoadMetadata& new_metadata) {
   // Throw away IPCs that are not relevant to the current navigation.
   // Two timing structures cannot refer to the same navigation if they indicate
   // that a navigation started at different times, so a new timing struct with a
   // different start time from an earlier struct is considered invalid.
   const bool valid_timing_descendent =
-      timing_.navigation_start.is_null() ||
-      timing_.navigation_start == new_timing.navigation_start;
+      merged_page_timing_.navigation_start.is_null() ||
+      merged_page_timing_.navigation_start == new_timing.navigation_start;
   if (!valid_timing_descendent) {
     RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING_DESCENDENT);
     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;
   }
   internal::PageLoadTimingStatus status = IsValidPageLoadTiming(new_timing);
   UMA_HISTOGRAM_ENUMERATION(internal::kPageLoadTimingStatus, status,
                             internal::LAST_PAGE_LOAD_TIMING_STATUS);
   if (status != internal::VALID) {
     RecordInternalError(ERR_BAD_TIMING_IPC_INVALID_TIMING);
     return;
   }
 
   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 = timing_;
-  timing_ = new_timing;
+  const PageLoadTiming last_timing = merged_page_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;
+  MergePaintTiming(base::TimeDelta(), new_timing.paint_timing,
+                   true /* is_main_frame */);
 
   const PageLoadMetadata last_metadata = main_frame_metadata_;
   main_frame_metadata_ = new_metadata;
   const PageLoadExtraInfo info = ComputePageLoadExtraInfo();
   for (const auto& observer : observers_) {
-    DispatchObserverTimingCallbacks(observer.get(), last_timing, new_timing,
-                                    last_metadata, info);
+    DispatchObserverTimingCallbacks(observer.get(), last_timing,
+                                    merged_page_timing_, last_metadata, info);
   }
 }
 
 void PageLoadTracker::OnStartedResource(
     const ExtraRequestStartInfo& extra_request_start_info) {
   for (const auto& observer : observers_) {
     observer->OnStartedResource(extra_request_start_info);
   }
 }
 
@@ skipping 175 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