Fix a load timing bug in the case of SPDY session reuse

net/url_request/url_request.cc

 // Copyright (c) 2012 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 "net/url_request/url_request.h"
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/compiler_specific.h"
@@ skipping 56 matching lines @@
   base::AutoLock lock(g_next_url_request_identifier_lock.Get());
   return g_next_url_request_identifier++;
 }
 
 // True once the first URLRequest was started.
 bool g_url_requests_started = false;
 
 // True if cookies are accepted by default.
 bool g_default_can_use_cookies = true;
 
+// When the URLRequest first assempts load timing information, it has the times
+// at which each event occurred.  The API requires the time which the request
+// was blocked on each phase.  This function handles the conversion.
+//
+// In the case of reusing a SPDY session or HTTP pipeline, old proxy results may
+// have been reused, so proxy resolution times may be before the request was
+// started.
+//
+// Due to preconnect and late binding, it is also possible for the connection
+// attempt to start before a request has been started, or proxy resolution
+// completed.
+//
+// This functions fixes both those cases.
+void FixupLoadTimingInfo(net::LoadTimingInfo* load_timing_info) {

[eroman, 2013/04/06 01:02:02]

The description is pretty clear on what this does, but the function name could
be improved.

[mmenke, 2013/04/08 15:31:24]

Renamed to "ConvertRealLoadTimesToBlockingTimes".  A bit of a mouthful, but it's
accurate, and not called a lot.  :)

+  DCHECK(!load_timing_info->request_start.is_null());
+
+  // Earliest time possible for the request to be blocking on connect events.
+  base::TimeTicks block_on_connect = load_timing_info->request_start;
+
+  if (!load_timing_info->proxy_resolve_start.is_null()) {
+    DCHECK(!load_timing_info->proxy_resolve_end.is_null());
+
+    // Make sure the proxy times are after request start.
+    if (load_timing_info->proxy_resolve_start < load_timing_info->request_start)
+      load_timing_info->proxy_resolve_start = load_timing_info->request_start;
+    if (load_timing_info->proxy_resolve_end < load_timing_info->request_start)
+      load_timing_info->proxy_resolve_end = load_timing_info->request_start;
+
+    // Connect times must also be after the proxy times.
+    block_on_connect = load_timing_info->proxy_resolve_end;
+  }
+
+  // Make sure connection times are after start and proxy times.
+
+  net::LoadTimingInfo::ConnectTiming* connect_timing =
+      &load_timing_info->connect_timing;
+  if (!connect_timing->dns_start.is_null()) {
+    DCHECK(!connect_timing->dns_end.is_null());
+    if (connect_timing->dns_start < block_on_connect)
+      connect_timing->dns_start = block_on_connect;
+    if (connect_timing->dns_end < block_on_connect)
+      connect_timing->dns_end = block_on_connect;
+  }
+
+  if (!connect_timing->connect_start.is_null()) {
+    DCHECK(!connect_timing->connect_end.is_null());
+    if (connect_timing->connect_start < block_on_connect)
+      connect_timing->connect_start = block_on_connect;
+    if (connect_timing->connect_end < block_on_connect)
+      connect_timing->connect_end = block_on_connect;
+  }
+
+  if (!connect_timing->ssl_start.is_null()) {
+    DCHECK(!connect_timing->ssl_end.is_null());
+    if (connect_timing->ssl_start < block_on_connect)
+      connect_timing->ssl_start = block_on_connect;
+    if (connect_timing->ssl_end < block_on_connect)
+      connect_timing->ssl_end = block_on_connect;
+  }
+}
+
 }  // namespace
 
 URLRequest::ProtocolFactory*
 URLRequest::Deprecated::RegisterProtocolFactory(const std::string& scheme,
                                                 ProtocolFactory* factory) {
   return URLRequest::RegisterProtocolFactory(scheme, factory);
 }
 
 void URLRequest::Deprecated::RegisterRequestInterceptor(
     Interceptor* interceptor) {
@@ skipping 879 matching lines @@
   if (delegate_)
     delegate_->OnReadCompleted(this, bytes_read);
 
   // Nothing below this line as OnReadCompleted may delete |this|.
 }
 
 void URLRequest::OnHeadersComplete() {
   // Cache load timing information now, as information will be lost once the
   // socket is closed and the ClientSocketHandle is Reset, which will happen
   // once the body is complete.  The start times should already be populated.
-  if (job_)
+  if (job_) {
     job_->GetLoadTimingInfo(&load_timing_info_);
+    FixupLoadTimingInfo(&load_timing_info_);

[eroman, 2013/04/06 01:02:02]

This seems fragile (different meanings at different levels). I can't think of a
problem at the moment, but seems like a subtle problem waiting to happen again.

[mmenke, 2013/04/06 01:35:24]

I agree...  Since we dig down all the way to the socket to get this information,
we could have the lower levels of the network stack do this logic - the
HttpTransaction can "fix" the proxy times if needed, and the socket itself can
"fix" the connect times.

The downside to this is I'm not sure it can reasonably be unit tested.  It also
somewhat masks the issue - the whole incremental retrieval at each level process
is a little weird.

Worth the switch?

+  }
 }
 
 void URLRequest::NotifyRequestCompleted() {
   // TODO(battre): Get rid of this check, according to willchan it should
   // not be needed.
   if (has_notified_completion_)
     return;
 
   is_pending_ = false;
   is_redirecting_ = false;
@@ skipping 25 matching lines @@
       new base::debug::StackTrace(NULL, 0);
   *stack_trace_copy = stack_trace;
   stack_trace_.reset(stack_trace_copy);
 }
 
 const base::debug::StackTrace* URLRequest::stack_trace() const {
   return stack_trace_.get();
 }
 
 }  // namespace net