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 ConvertRealLoadTimesToBlockingTimes(
+    net::LoadTimingInfo* load_timing_info) {
+  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_);
+    ConvertRealLoadTimesToBlockingTimes(&load_timing_info_);
+  }
 }
 
 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