Associate a main resource request with its PageLoadTracker.

chrome/browser/page_load_metrics/metrics_web_contents_observer.cc

Index: chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
diff --git a/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc b/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
index 926978a722908430d4ab523137ffa0f6886562dd..65a0264a6ccd3430746ccab0b609178b3fa42ad0 100644
--- a/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
+++ b/chrome/browser/page_load_metrics/metrics_web_contents_observer.cc
@@ -20,6 +20,7 @@
 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h"
 #include "chrome/common/page_load_metrics/page_load_timing.h"
 #include "content/public/browser/browser_thread.h"
+#include "content/public/browser/global_request_id.h"
 #include "content/public/browser/navigation_details.h"
 #include "content/public/browser/navigation_handle.h"
 #include "content/public/browser/render_frame_host.h"
@@ -175,29 +176,67 @@ void MetricsWebContentsObserver::WillStartNavigationRequest(
           chain_size_same_url)));
 }
 
+PageLoadTracker* MetricsWebContentsObserver::GetTrackerOrNullForRequest(
+    const content::GlobalRequestID& request_id,
+    content::ResourceType resource_type,
+    base::TimeTicks creation_time) {
+  if (resource_type == content::RESOURCE_TYPE_MAIN_FRAME) {
+    // The main frame request can complete either before or after commit, so we
+    // look at both provisional loads and the committed load to find a
+    // PageLoadTracker with a matching request id. See
+    // https://docs.google.com/document/d/1dZP0si0IKEMeVKGsohJ3fFWiKqh3nZBtuTFVkAPSXYM/edit

[Charlie Harrison, 2017/01/13 15:56:23]

optional: Can you shorten this with a https://goo.gl/ link?

[Bryan McQuade, 2017/01/17 15:06:26]

done

+    // for more details.
+    for (const auto& kv : provisional_loads_) {

[RyanSturm, 2017/01/13 15:39:50]

I'd actually suggest going a step further for the cases where the load hasn't
committed yet. If the request completes before the browser is ready to commit
due to some deferral in NavigationThrottle, you might want to store this request
info for when these provisional_loads_ commit or are deleted.

For instance, if you don't find a match in the committed loads, you could send a
copy of ExtraRequestInfo + request_id to each provisional load, when the load is
switched from provisional to committed, you could process the matching
ExtraRequestInfo (if there is one) in the observers at that point and throw the
rest out.

I bring this up because I think ReadyToCommitNavigation happens very shortly
before DidFinishNavigation (maybe even the same stack?, I'm not sure how
transfer navigations work here either), so you might not be buying anything for
requests that complete before commit.

[Bryan McQuade, 2017/01/13 15:47:14]

Ah, interesting, what problem would we solve by storing and deferring for non
committed loads? I don't see any significant differences in behavior & it adds
complexity to buffer until commit (it's not something we generally do with other
activity that can happen pre-commit, such as redirects or page visibility state
changes. My inclination is to keep this simple, since I don't think it affects
the observers in any significant way and just adds complexity here - they'll get
the OnLoadedResource callback before commit, and can increment any byte counters
etc, just as they would if we invoke the same callback later after commit.

[Bryan McQuade, 2017/01/13 15:53:17]

Ah, maybe you are concerned that we won't have the GlobalRequestID at the point
the response completes? My analysis of call stack flows in the associated doc
suggests that's not the case, and my local testing confirms this. It's an
interesting idea to hold on to the ExtraRequestInfo just in case - that does
make the code more resilient. But I'm not sure it's worth the complexity
tradeoff given that the call ordering guarantees seem to match what we expect.

I'd propose that we proceed w/ this or something similar for now, and before we
add complexity, we have a bigger discussion w/ clamy to understand constraints
here & make changes as needed.

[RyanSturm, 2017/01/13 16:15:46]

Like you said, clamy@ is the expert here, but I believe it is possible for a
response to be deferred by a navigation throttle in
NavigationHandleImpl::WillProcessResponse. 

For example:
ClearSiteDataThrottle::WillProcessResponse() can defer the response preventing
commit for some time. If the main page resource is small, I believe this can
cause the URLRequest completion event to get to the UI thread before the load is
committed. Admittedly, I have not verified it or dug through NavigationThrottles
to know exactly what they do.

It's not really evident to me how long a navigation throttle can defer
navigations.

I'm not opposed to this landing, and I would be interested to know how many 0
bytes cases this fixes. That said, knowing the complexity of chrome and that
there is a deferral mechanism that will defer committing while the IO thread
runs, I'd be surprised if this didn't run into problems later.

+      PageLoadTracker* candidate = kv.second.get();
+      if (candidate->HasMatchingNavigationRequestID(request_id)) {
+        return candidate;
+      }
+    }
+    if (committed_load_ &&
+        committed_load_->HasMatchingNavigationRequestID(request_id)) {
+      return committed_load_.get();
+    }
+  } else {
+    // Non main frame resources are always associated with the currently
+    // committed load. If the resource request was started before this
+    // navigation then it should be ignored.
+
+    // TODO(jkarlin): There is a race here. Consider the following sequence:
+    // 1. renderer has a committed page A
+    // 2. navigation is initiated to page B
+    // 3. page A initiates URLRequests (e.g. in the unload handler)
+    // 4. page B commits
+    // 5. the URLRequests initiated by A complete

[Charlie Harrison, 2017/01/13 15:56:23]

Shouldn't the request be cancelled? I guess it could be a detachable request
link link prefetch.

[Bryan McQuade, 2017/01/17 15:06:26]

Unfortunately that doesn't seem to be the case. I saw requests on twitter.com
get associated with the next committed load in multiple local tests.

+    // In the above example, the URLRequests initiated by A will be attributed
+    // to page load B. This should be relatively rare but we may want to fix
+    // this at some point. We could fix this by comparing the URLRequest
+    // creation time against the committed load's commit time, however more
+    // investigation is needed to confirm that all cases would be handled
+    // correctly (for example Link: preloads).
+    if (committed_load_ &&
+        creation_time >= committed_load_->navigation_start()) {
+      return committed_load_.get();
+    }
+  }
+  return nullptr;
+}
+
 void MetricsWebContentsObserver::OnRequestComplete(
+    const content::GlobalRequestID& request_id,
     content::ResourceType resource_type,
     bool was_cached,
     bool used_data_reduction_proxy,
     int64_t raw_body_bytes,
     int64_t original_content_length,
     base::TimeTicks creation_time) {
-  // If the navigation hasn't committed yet then we'll miss the resource (this
-  // happens on the new tab page). Also, if the resource request was started
-  // before this navigation then it should be ignored.
-  // TODO(jkarlin): There is a race here. If a renderer starts URLRequests for
-  // page A after navigating (but before comitting) to page B, then page A's
-  // requests might wind up counting toward page B's size. This should be
-  // relatively rare but we may want to fix this at some point.
-  if (!committed_load_ || creation_time < committed_load_->navigation_start()) {
-    return;
+  PageLoadTracker* tracker =
+      GetTrackerOrNullForRequest(request_id, resource_type, creation_time);
+  if (tracker) {
+    ExtraRequestInfo extra_request_info(
+        was_cached, raw_body_bytes, used_data_reduction_proxy,
+        was_cached ? 0 : original_content_length);
+    tracker->OnLoadedResource(extra_request_info);
   }
-
-  ExtraRequestInfo extra_request_info(was_cached, raw_body_bytes,
-                                      used_data_reduction_proxy,
-                                      was_cached ? 0 : original_content_length);
-
-  committed_load_->OnLoadedResource(extra_request_info);
 }
 
 const PageLoadExtraInfo
@@ -206,6 +245,14 @@ MetricsWebContentsObserver::GetPageLoadExtraInfoForCommittedLoad() {
   return committed_load_->ComputePageLoadExtraInfo();
 }
 
+void MetricsWebContentsObserver::ReadyToCommitNavigation(
+    content::NavigationHandle* navigation_handle) {
+  auto it = provisional_loads_.find(navigation_handle);
+  if (it == provisional_loads_.end())
+    return;
+  it->second->ReadyToCommit(navigation_handle);
+}
+
 void MetricsWebContentsObserver::DidFinishNavigation(
     content::NavigationHandle* navigation_handle) {
   if (!navigation_handle->IsInMainFrame())