Fix bug which caused DNS time not to be reported by LoadTimingObserver.

The problem was the LogBoundConnectJobToRequest() sets
SOCKET_POOL_BOUND_TO_CONNECT_JOB after RemoveConnectJob() ends
SOCKET_POOL_CONNECT_JOB. Since there is no chance to return to the event loop,
it is safe (although fragile), to store the last connect job record and access
that on SOCKET_POOL_BOUND_TO_CONNECT_JOB.

Also, after fixing the DNS issue, it became apparent that what was being
measured as connect time actually included more than just the TCP connect. So I
fixed that as well.

BUG=50229
TEST=LoadTimingObserverTest.*

Review URL: http://codereview.chromium.org/3028026

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@53945 0039d316-1c4b-4281-b951-d872f2087c98

4 files changed, 25 insertions, 15 deletions

diff --git a/chrome/browser/net/load_timing_observer.cc b/chrome/browser/net/load_timing_observer.cc
index d0e0485..8d51278 100644
--- a/chrome/browser/net/load_timing_observer.cc
+++ b/chrome/browser/net/load_timing_observer.cc
@@ -48,7 +48,8 @@ LoadTimingObserver::URLRequestRecord::URLRequestRecord()
       socket_reused(false) {
 }
 
-LoadTimingObserver::LoadTimingObserver() {
+LoadTimingObserver::LoadTimingObserver()
+    : last_connect_job_id_(net::NetLog::Source::kInvalidId) {
 }
 
 LoadTimingObserver::~LoadTimingObserver() {
@@ -118,7 +119,7 @@ void LoadTimingObserver::OnAddURLRequestEntry(
 
   ResourceLoaderBridge::LoadTimingInfo& timing = record->timing;
 
-  switch(type) {
+  switch (type) {
     case net::NetLog::TYPE_PROXY_SERVICE:
       if (is_begin)
         timing.proxy_start = TimeTicksToOffset(time, record);
@@ -135,12 +136,12 @@ void LoadTimingObserver::OnAddURLRequestEntry(
       {
         uint32 connect_job_id = static_cast<net::NetLogSourceParameter*>(
             params)->value().id;
-        ConnectJobToRecordMap::iterator it =
-            connect_job_to_record_.find(connect_job_id);
-        if (it != connect_job_to_record_.end() &&
-                !it->second.dns_start.is_null()) {
-          timing.dns_start = TimeTicksToOffset(it->second.dns_start, record);
-          timing.dns_end = TimeTicksToOffset(it->second.dns_end, record);
+        if (last_connect_job_id_ == connect_job_id &&
+            !last_connect_job_record_.dns_start.is_null()) {
+          timing.dns_start =
+              TimeTicksToOffset(last_connect_job_record_.dns_start, record);
+          timing.dns_end =
+              TimeTicksToOffset(last_connect_job_record_.dns_end, record);
         }
       }
       break;
@@ -154,8 +155,8 @@ void LoadTimingObserver::OnAddURLRequestEntry(
         SocketToRecordMap::iterator it =
             socket_to_record_.find(record->socket_log_id);
         if (it != socket_to_record_.end() && !it->second.ssl_start.is_null()) {
-            timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
-            timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
+          timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
+          timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
         }
       }
       break;
@@ -201,7 +202,13 @@ void LoadTimingObserver::OnAddConnectJobEntry(
       connect_job_to_record_.insert(
           std::make_pair(source.id, ConnectJobRecord()));
     } else if (is_end) {
-      connect_job_to_record_.erase(source.id);
+      ConnectJobToRecordMap::iterator it =
+          connect_job_to_record_.find(source.id);
+      if (it != connect_job_to_record_.end()) {
+        last_connect_job_id_ = it->first;
+        last_connect_job_record_ = it->second;
+        connect_job_to_record_.erase(it);
+      }
     }
   } else if (type == net::NetLog::TYPE_HOST_RESOLVER_IMPL) {
     ConnectJobToRecordMap::iterator it =
diff --git a/chrome/browser/net/load_timing_observer.h b/chrome/browser/net/load_timing_observer.h
index 8b4ca19b..873e224 100644
--- a/chrome/browser/net/load_timing_observer.h
+++ b/chrome/browser/net/load_timing_observer.h
@@ -81,6 +81,8 @@ class LoadTimingObserver : public ChromeNetLog::Observer {
   URLRequestToRecordMap url_request_to_record_;
   ConnectJobToRecordMap connect_job_to_record_;
   SocketToRecordMap socket_to_record_;
+  uint32 last_connect_job_id_;
+  ConnectJobRecord last_connect_job_record_;
 
   DISALLOW_COPY_AND_ASSIGN(LoadTimingObserver);
 };
diff --git a/chrome/browser/net/load_timing_observer_unittest.cc b/chrome/browser/net/load_timing_observer_unittest.cc
index 6eae903..8ded133 100644
--- a/chrome/browser/net/load_timing_observer_unittest.cc
+++ b/chrome/browser/net/load_timing_observer_unittest.cc
@@ -223,6 +223,7 @@ TEST(LoadTimingObserverTest, DnsTime) {
                 NULL);
   current_time += TimeDelta::FromSeconds(2);
   AddEndEntry(observer, connect_source, NetLog::TYPE_HOST_RESOLVER_IMPL, NULL);
+  AddEndConnectJobEntries(observer, 1);
 
   // Bind to connect job.
   scoped_refptr<net::NetLogSourceParameter> params(
diff --git a/webkit/glue/resource_loader_bridge.h b/webkit/glue/resource_loader_bridge.h
index 7d85bd3..e4d439f 100644
--- a/webkit/glue/resource_loader_bridge.h
+++ b/webkit/glue/resource_loader_bridge.h
@@ -117,12 +117,12 @@ class ResourceLoaderBridge {
     // The time that DNS lookup ended. For reused sockets this time is -1.
     int32 dns_end;
 
-    // The time that establishing connection started. For reused sockets
-    // this time is -1. Connect time includes dns time.
+    // The time that establishing connection started. Connect time includes
+    // DNS, blocking, TCP, TCP retries and SSL time.
     int32 connect_start;
 
-    // The time that establishing connection ended. For reused sockets this
-    // time is -1. Connect time includes dns time.
+    // The time that establishing connection ended. Connect time includes
+    // DNS, blocking, TCP, TCP retries and SSL time.
     int32 connect_end;
 
     // The time at which SSL handshake started. For non-HTTPS requests this