LoadTiming implementation in net, part 1.

Calculate connection timing information in ConnectJobs,
add store it in ClientSocketHandles.

BUG=77446
Review URL: https://codereview.chromium.org/11428150

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

net/base/load_timing_info.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/base/load_timing_info.h"
+
+#include "net/base/net_log.h"
+
+namespace net {
+
+LoadTimingInfo::ConnectTiming::ConnectTiming() {}
+
+LoadTimingInfo::ConnectTiming::~ConnectTiming() {}
+
+LoadTimingInfo::LoadTimingInfo() : socket_reused(false),
+                                   socket_log_id(NetLog::Source::kInvalidId) {
+}
+
+LoadTimingInfo::~LoadTimingInfo() {}
+
+}  // namespace net
+

net/base/load_timing_info.h

+// 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.
+
+#ifndef NET_BASE_LOAD_TIMING_INFO_H_
+#define NET_BASE_LOAD_TIMING_INFO_H_
+
+#include "base/basictypes.h"
+#include "base/time.h"
+#include "net/base/net_export.h"
+
+namespace net {
+
+// All events that do not apply to a request have null times.  For non-HTTP
+// requests, all times other than the request_start times are null.
+//
+// The general order for events is:
+// request_start
+// proxy_start
+// proxy_end
+// *dns_start
+// *dns_end
+// *connect_start
+// *ssl_start
+// *ssl_end
+// *connect_end
+// send_start
+// send_end
+// receive_headers_end
+//
+// Those times without an asterisk are computed by the URLRequest, or by objects
+// it directly creates and always owns.  Those with an asterisk are computed
+// by the connection attempt itself.  Since the connection attempt may be
+// started before a URLRequest, the starred times may occur before, during, or
+// after the request_start and proxy events.
+struct NET_EXPORT LoadTimingInfo {
+  // Contains the LoadTimingInfo events related to establishing a connection.
+  // These are all set by ConnectJobs.
+  struct NET_EXPORT_PRIVATE ConnectTiming {
+    ConnectTiming();
+    ~ConnectTiming();
+
+    // The time spent looking up the host's DNS address.  Null for requests that
+    // used proxies to look up the DNS address.  Also null for SOCKS4 proxies,
+    // since the DNS address is only looked up after the connection is
+    // established, which results in unexpected event ordering.
+    // TODO(mmenke):  The SOCKS4 event ordering could be refactored to allow
+    //                these times to be non-null.
+    base::TimeTicks dns_start;
+    base::TimeTicks dns_end;
+
+    // The time spent establishing the connection. Connect time includes proxy
+    // connect times (Though not proxy_resolve times), DNS lookup times, time
+    // spent waiting in certain queues, TCP, and SSL time.
+    // TODO(mmenke):  For proxies, this includes time spent blocking on higher
+    //                level socket pools.  Fix this.
+    // TODO(mmenke):  Retried connections to the same server should apparently
+    //                be included in this time.  Consider supporting that.
+    //                Since the network stack has multiple notions of a "retry",
+    //                handled at different levels, this may not be worth
+    //                worrying about - backup jobs, reused socket failure,
+    //                multiple round authentication.
+    base::TimeTicks connect_start;
+    base::TimeTicks connect_end;
+
+    // The time when the SSL handshake started / completed. For non-HTTPS
+    // requests these are null.  These times are only for the SSL connection to
+    // the final destination server, not an SSL/SPDY proxy.
+    base::TimeTicks ssl_start;
+    base::TimeTicks ssl_end;
+  };
+
+  LoadTimingInfo();
+  ~LoadTimingInfo();
+
+  // True if the socket was reused.  When true, DNS, connect, and SSL times
+  // will all be null.  When false, those times may be null, too, for non-HTTP
+  // requests, or when they don't apply to a request.
+  bool socket_reused;
+
+  // Unique socket ID, can be used to identify requests served by the same
+  // socket.
+  // TODO(mmenke):  Do something reasonable for SPDY proxies.
+  uint32 socket_log_id;
+
+  // Start time as a base::Time, so times can be coverted into actual times.
+  // Other times are recorded as TimeTicks so they are not affected by clock
+  // changes.
+  base::Time request_start_time;
+
+  base::TimeTicks request_start;
+
+  // The time spent determing which proxy to use.  Null when there is no PAC.
+  base::TimeTicks proxy_resolve_start;
+  base::TimeTicks proxy_resolve_end;
+
+  ConnectTiming connect_timing;
+
+  // The time that sending HTTP request started / ended.
+  base::TimeTicks send_start;
+  base::TimeTicks send_end;
+
+  // The time at which the end of the HTTP headers were received.
+  base::TimeTicks receive_headers_end;
+};
+
+}  // namespace net
+
+#endif  // NET_BASE_LOAD_TIMING_INFO_H_

net/net.gyp

@@ -180,6 +180,8 @@
         'base/load_flags_list.h',
         'base/load_states.h',
         'base/load_states_list.h',
+        'base/load_timing_info.cc',
+        'base/load_timing_info.h',
         'base/mapped_host_resolver.cc',
         'base/mapped_host_resolver.h',
         'base/mime_sniffer.cc',

net/socket/client_socket_handle.cc

@@ -62,6 +62,7 @@ void ClientSocketHandle::ResetInternal(bool cancel) {
   idle_time_ = base::TimeDelta();
   init_time_ = base::TimeTicks();
   setup_time_ = base::TimeDelta();
+  connect_timing_ = LoadTimingInfo::ConnectTiming();
   pool_id_ = -1;
 }
 
@@ -103,6 +104,24 @@ void ClientSocketHandle::RemoveLayeredPool(LayeredPool* layered_pool) {
   }
 }
 
+bool ClientSocketHandle::GetLoadTimingInfo(
+    bool is_reused,
+    LoadTimingInfo* load_timing_info) const {
+  // Only return load timing information when there's a socket.
+  if (!socket_)
+    return false;
+
+  load_timing_info->socket_log_id = socket_->NetLog().source().id;
+  load_timing_info->socket_reused = is_reused;
+
+  // No times if the socket is reused.
+  if (is_reused)
+    return true;
+
+  load_timing_info->connect_timing = connect_timing_;
+  return true;
+}
+
 void ClientSocketHandle::OnIOComplete(int result) {
   CompletionCallback callback = user_callback_;
   user_callback_.Reset();

net/socket/client_socket_handle.h

@@ -13,6 +13,7 @@
 #include "base/time.h"
 #include "net/base/completion_callback.h"
 #include "net/base/load_states.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_export.h"
 #include "net/base/net_log.h"
@@ -106,6 +107,14 @@ class NET_EXPORT ClientSocketHandle {
   // Returns the time between Init() and when is_initialized() becomes true.
   base::TimeDelta setup_time() const { return setup_time_; }
 
+  // Sets the portion of LoadTimingInfo related to connection establishment, and
+  // the socket id.  |is_reused| is needed because the handle may not have full
+  // reuse information.  |load_timing_info| must have all default values when
+  // called. Returns false and makes no changes to |load_timing_info| when
+  // |socket_| is NULL.
+  bool GetLoadTimingInfo(bool is_reused,
+                         LoadTimingInfo* load_timing_info) const;
+
   // Used by ClientSocketPool to initialize the ClientSocketHandle.
   void set_is_reused(bool is_reused) { is_reused_ = is_reused; }
   void set_socket(StreamSocket* s) { socket_.reset(s); }
@@ -150,6 +159,12 @@ class NET_EXPORT ClientSocketHandle {
       return UNUSED_IDLE;
     }
   }
+  const LoadTimingInfo::ConnectTiming& connect_timing() const {
+    return connect_timing_;
+  }
+  void set_connect_timing(const LoadTimingInfo::ConnectTiming& connect_timing) {
+    connect_timing_ = connect_timing;
+  }
 
  private:
   // Called on asynchronous completion of an Init() request.
@@ -185,6 +200,9 @@ class NET_EXPORT ClientSocketHandle {
 
   NetLog::Source requesting_source_;
 
+  // Timing information is set when a connection is successfully established.
+  LoadTimingInfo::ConnectTiming connect_timing_;
+
   DISALLOW_COPY_AND_ASSIGN(ClientSocketHandle);
 };
 

net/socket/client_socket_pool_base.cc

@@ -126,10 +126,12 @@ void ConnectJob::ResetTimer(base::TimeDelta remaining_time) {
 }
 
 void ConnectJob::LogConnectStart() {
+  connect_timing_.connect_start = base::TimeTicks::Now();
   net_log().BeginEvent(NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT);
 }
 
 void ConnectJob::LogConnectCompletion(int net_error) {
+  connect_timing_.connect_end = base::TimeTicks::Now();
   net_log().EndEventWithNetErrorCode(
       NetLog::TYPE_SOCKET_POOL_CONNECT_JOB_CONNECT, net_error);
 }
@@ -383,7 +385,8 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
     LogBoundConnectJobToRequest(connect_job->net_log().source(), request);
     if (!preconnecting) {
       HandOutSocket(connect_job->ReleaseSocket(), false /* not reused */,
-                    handle, base::TimeDelta(), group, request->net_log());
+                    connect_job->connect_timing(), handle, base::TimeDelta(),
+                    group, request->net_log());
     } else {
       AddIdleSocket(connect_job->ReleaseSocket(), group);
     }
@@ -408,8 +411,9 @@ int ClientSocketPoolBaseHelper::RequestSocketInternal(
       error_socket = connect_job->ReleaseSocket();
     }
     if (error_socket) {
-      HandOutSocket(error_socket, false /* not reused */, handle,
-                    base::TimeDelta(), group, request->net_log());
+      HandOutSocket(error_socket, false /* not reused */,
+                    connect_job->connect_timing(), handle, base::TimeDelta(),
+                    group, request->net_log());
     } else if (group->IsEmpty()) {
       RemoveGroup(group_name);
     }
@@ -475,6 +479,7 @@ bool ClientSocketPoolBaseHelper::AssignIdleSocketToRequest(
     HandOutSocket(
         idle_socket.socket,
         idle_socket.socket->WasEverUsed(),
+        LoadTimingInfo::ConnectTiming(),
         request->handle(),
         idle_time,
         group,
@@ -855,7 +860,10 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
 
   scoped_ptr<StreamSocket> socket(job->ReleaseSocket());
 
+  // Copies of these are needed because |job| may be deleted before they are
+  // accessed.
   BoundNetLog job_log = job->net_log();
+  LoadTimingInfo::ConnectTiming connect_timing = job->connect_timing();
 
   if (result == OK) {
     DCHECK(socket.get());
@@ -865,8 +873,8 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
           group->mutable_pending_requests()->begin(), group));
       LogBoundConnectJobToRequest(job_log.source(), r.get());
       HandOutSocket(
-          socket.release(), false /* unused socket */, r->handle(),
-          base::TimeDelta(), group, r->net_log());
+          socket.release(), false /* unused socket */, connect_timing,
+          r->handle(), base::TimeDelta(), group, r->net_log());
       r->net_log().EndEvent(NetLog::TYPE_SOCKET_POOL);
       InvokeUserCallbackLater(r->handle(), r->callback(), result);
     } else {
@@ -886,11 +894,11 @@ void ClientSocketPoolBaseHelper::OnConnectJobComplete(
       RemoveConnectJob(job, group);
       if (socket.get()) {
         handed_out_socket = true;
-        HandOutSocket(socket.release(), false /* unused socket */, r->handle(),
-                      base::TimeDelta(), group, r->net_log());
+        HandOutSocket(socket.release(), false /* unused socket */,
+                      connect_timing, r->handle(), base::TimeDelta(), group,
+                      r->net_log());
       }
-      r->net_log().EndEventWithNetErrorCode(NetLog::TYPE_SOCKET_POOL,
-                                            result);
+      r->net_log().EndEventWithNetErrorCode(NetLog::TYPE_SOCKET_POOL, result);
       InvokeUserCallbackLater(r->handle(), r->callback(), result);
     } else {
       RemoveConnectJob(job, group);
@@ -977,6 +985,7 @@ void ClientSocketPoolBaseHelper::ProcessPendingRequest(
 void ClientSocketPoolBaseHelper::HandOutSocket(
     StreamSocket* socket,
     bool reused,
+    const LoadTimingInfo::ConnectTiming& connect_timing,
     ClientSocketHandle* handle,
     base::TimeDelta idle_time,
     Group* group,
@@ -986,6 +995,7 @@ void ClientSocketPoolBaseHelper::HandOutSocket(
   handle->set_is_reused(reused);
   handle->set_idle_time(idle_time);
   handle->set_pool_id(pool_generation_number_);
+  handle->set_connect_timing(connect_timing);
 
   if (reused) {
     net_log.AddEvent(

net/socket/client_socket_pool_base.h

@@ -38,6 +38,7 @@
 #include "net/base/address_list.h"
 #include "net/base/completion_callback.h"
 #include "net/base/load_states.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_export.h"
 #include "net/base/net_log.h"
@@ -104,6 +105,10 @@ class NET_EXPORT_PRIVATE ConnectJob {
   // additional error state to the ClientSocketHandle (post late-binding).
   virtual void GetAdditionalErrorState(ClientSocketHandle* handle) {}
 
+  const LoadTimingInfo::ConnectTiming& connect_timing() const {
+    return connect_timing_;
+  }
+
   const BoundNetLog& net_log() const { return net_log_; }
 
  protected:
@@ -112,6 +117,9 @@ class NET_EXPORT_PRIVATE ConnectJob {
   void NotifyDelegateOfCompletion(int rv);
   void ResetTimer(base::TimeDelta remainingTime);
 
+  // Connection establishment timing information.
+  LoadTimingInfo::ConnectTiming connect_timing_;
+
  private:
   virtual int ConnectInternal() = 0;
 
@@ -493,6 +501,7 @@ class NET_EXPORT_PRIVATE ClientSocketPoolBaseHelper
   // Assigns |socket| to |handle| and updates |group|'s counters appropriately.
   void HandOutSocket(StreamSocket* socket,
                      bool reused,
+                     const LoadTimingInfo::ConnectTiming& connect_timing,
                      ClientSocketHandle* handle,
                      base::TimeDelta time_idle,
                      Group* group,

net/socket/socket_test_util.cc

@@ -16,6 +16,7 @@
 #include "net/base/address_family.h"
 #include "net/base/address_list.h"
 #include "net/base/auth.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/base/ssl_info.h"
 #include "net/http/http_network_session.h"
@@ -1537,6 +1538,16 @@ void MockTransportClientSocketPool::MockConnectJob::OnConnect(int rv) {
     return;
   if (rv == OK) {
     handle_->set_socket(socket_.release());
+
+    // Needed for socket pool tests that layer other sockets on top of mock
+    // sockets.
+    LoadTimingInfo::ConnectTiming connect_timing;
+    base::TimeTicks now = base::TimeTicks::Now();
+    connect_timing.dns_start = now;
+    connect_timing.dns_end = now;
+    connect_timing.connect_start = now;
+    connect_timing.connect_end = now;
+    handle_->set_connect_timing(connect_timing);
   } else {
     socket_.reset();
   }

net/socket/socks_client_socket_pool_unittest.cc

@@ -7,6 +7,7 @@
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/time.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_errors.h"
 #include "net/base/test_completion_callback.h"
@@ -23,6 +24,33 @@ namespace {
 const int kMaxSockets = 32;
 const int kMaxSocketsPerGroup = 6;
 
+// Make sure |handle|'s load times are set correctly.  Only connect times should
+// be set.
+void TestLoadTimingInfo(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  // None of these tests use a NetLog.
+  EXPECT_EQ(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+
+  EXPECT_FALSE(load_timing_info.connect_timing.connect_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.connect_end);
+
+  // None of these should be set by the socket handle.
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
 class SOCKSClientSocketPoolTest : public testing::Test {
  protected:
   class SOCKS5MockData {
@@ -107,6 +135,7 @@ TEST_F(SOCKSClientSocketPoolTest, Simple) {
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SOCKSClientSocketPoolTest, Async) {
@@ -124,6 +153,7 @@ TEST_F(SOCKSClientSocketPoolTest, Async) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SOCKSClientSocketPoolTest, TransportConnectError) {

net/socket/ssl_client_socket_pool.cc

@@ -129,7 +129,7 @@ void SSLConnectJob::GetAdditionalErrorState(ClientSocketHandle* handle) {
         transport_socket_handle_.release());
   }
   handle->set_ssl_error_response_info(error_response_info_);
-  if (!ssl_connect_start_time_.is_null())
+  if (!connect_timing_.ssl_start.is_null())
     handle->set_is_ssl_error(true);
 }
 
@@ -259,7 +259,22 @@ int SSLConnectJob::DoSSLConnect() {
   next_state_ = STATE_SSL_CONNECT_COMPLETE;
   // Reset the timeout to just the time allowed for the SSL handshake.
   ResetTimer(base::TimeDelta::FromSeconds(kSSLHandshakeTimeoutInSeconds));
-  ssl_connect_start_time_ = base::TimeTicks::Now();
+
+  // If the handle has a fresh socket, get its connect start and DNS times.
+  // This should always be the case.
+  const LoadTimingInfo::ConnectTiming& socket_connect_timing =
+      transport_socket_handle_->connect_timing();
+  if (!transport_socket_handle_->is_reused() &&
+      !socket_connect_timing.connect_start.is_null()) {
+    // Overwriting |connect_start| serves two purposes - it adjusts timing so
+    // |connect_start| doesn't include dns times, and it adjusts the time so
+    // as not to include time spent waiting for an idle socket.
+    connect_timing_.connect_start = socket_connect_timing.connect_start;
+    connect_timing_.dns_start = socket_connect_timing.dns_start;
+    connect_timing_.dns_end = socket_connect_timing.dns_end;
+  }
+
+  connect_timing_.ssl_start = base::TimeTicks::Now();
 
   ssl_socket_.reset(client_socket_factory_->CreateSSLClientSocket(
       transport_socket_handle_.release(), params_->host_and_port(),
@@ -268,6 +283,8 @@ int SSLConnectJob::DoSSLConnect() {
 }
 
 int SSLConnectJob::DoSSLConnectComplete(int result) {
+  connect_timing_.ssl_end = base::TimeTicks::Now();
+
   SSLClientSocket::NextProtoStatus status =
       SSLClientSocket::kNextProtoUnsupported;
   std::string proto;
@@ -302,9 +319,9 @@ int SSLConnectJob::DoSSLConnectComplete(int result) {
 
   if (result == OK ||
       ssl_socket_->IgnoreCertError(result, params_->load_flags())) {
-    DCHECK(ssl_connect_start_time_ != base::TimeTicks());
+    DCHECK(!connect_timing_.ssl_start.is_null());
     base::TimeDelta connect_duration =
-        base::TimeTicks::Now() - ssl_connect_start_time_;
+        connect_timing_.ssl_end - connect_timing_.ssl_start;
     if (using_spdy) {
       UMA_HISTOGRAM_CUSTOM_TIMES("Net.SpdyConnectionLatency",
                                  connect_duration,

net/socket/ssl_client_socket_pool.h

@@ -153,9 +153,6 @@ class SSLConnectJob : public ConnectJob {
   scoped_ptr<ClientSocketHandle> transport_socket_handle_;
   scoped_ptr<SSLClientSocket> ssl_socket_;
 
-  // The time the DoSSLConnect() method was called.
-  base::TimeTicks ssl_connect_start_time_;
-
   HttpResponseInfo error_response_info_;
 
   DISALLOW_COPY_AND_ASSIGN(SSLConnectJob);

net/socket/ssl_client_socket_pool_unittest.cc

@@ -11,6 +11,7 @@
 #include "base/utf_string_conversions.h"
 #include "net/base/auth.h"
 #include "net/base/cert_verifier.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_errors.h"
 #include "net/base/ssl_config_service_defaults.h"
@@ -39,6 +40,66 @@ namespace {
 const int kMaxSockets = 32;
 const int kMaxSocketsPerGroup = 6;
 
+// Make sure |handle|'s load times are set correctly.  DNS and connect start
+// times comes from mock client sockets in these tests, so primarily serves to
+// check those times were copied, and ssl times / connect end are set correctly.
+void TestLoadTimingInfo(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  // None of these tests use a NetLog.
+  EXPECT_EQ(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.dns_start,
+            load_timing_info.connect_timing.dns_end);
+  EXPECT_LE(load_timing_info.connect_timing.dns_end,
+            load_timing_info.connect_timing.connect_start);
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.ssl_start);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_start,
+            load_timing_info.connect_timing.ssl_end);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_end,
+            load_timing_info.connect_timing.connect_end);
+
+  // None of these should be set by the socket handle.
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
+// Just like TestLoadTimingInfo, except DNS times are expected to be null, for
+// tests over proxies that do DNS lookups themselves.
+void TestLoadTimingInfoNoDns(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  // None of these tests use a NetLog.
+  EXPECT_EQ(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_end.is_null());
+  EXPECT_FALSE(load_timing_info.connect_timing.connect_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.ssl_start);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_start,
+            load_timing_info.connect_timing.ssl_end);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_end,
+            load_timing_info.connect_timing.connect_end);
+
+  // None of these should be set by the socket handle.
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
 class SSLClientSocketPoolTest : public testing::Test {
  protected:
   SSLClientSocketPoolTest()
@@ -236,6 +297,7 @@ TEST_F(SSLClientSocketPoolTest, BasicDirect) {
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, BasicDirectAsync) {
@@ -259,6 +321,7 @@ TEST_F(SSLClientSocketPoolTest, BasicDirectAsync) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, DirectCertError) {
@@ -282,6 +345,7 @@ TEST_F(SSLClientSocketPoolTest, DirectCertError) {
   EXPECT_EQ(ERR_CERT_COMMON_NAME_INVALID, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, DirectSSLError) {
@@ -330,6 +394,7 @@ TEST_F(SSLClientSocketPoolTest, DirectWithNPN) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
 }
@@ -381,6 +446,7 @@ TEST_F(SSLClientSocketPoolTest, DirectGotSPDY) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
@@ -413,6 +479,7 @@ TEST_F(SSLClientSocketPoolTest, DirectGotBonusSPDY) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
@@ -483,6 +550,9 @@ TEST_F(SSLClientSocketPoolTest, SOCKSBasic) {
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  // SOCKS5 generally has no DNS times, but the mock SOCKS5 sockets used here
+  // don't go through the real logic, unlike in the HTTP proxy tests.
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, SOCKSBasicAsync) {
@@ -506,6 +576,9 @@ TEST_F(SSLClientSocketPoolTest, SOCKSBasicAsync) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  // SOCKS5 generally has no DNS times, but the mock SOCKS5 sockets used here
+  // don't go through the real logic, unlike in the HTTP proxy tests.
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, HttpProxyFail) {
@@ -580,6 +653,7 @@ TEST_F(SSLClientSocketPoolTest, HttpProxyBasic) {
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoNoDns(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, HttpProxyBasicAsync) {
@@ -614,6 +688,7 @@ TEST_F(SSLClientSocketPoolTest, HttpProxyBasicAsync) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoNoDns(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, NeedProxyAuth) {

net/socket/transport_client_socket_pool.cc

@@ -163,6 +163,8 @@ int TransportConnectJob::DoLoop(int result) {
 
 int TransportConnectJob::DoResolveHost() {
   next_state_ = STATE_RESOLVE_HOST_COMPLETE;
+  connect_timing_.dns_start = base::TimeTicks::Now();
+
   return resolver_.Resolve(
       params_->destination(), &addresses_,
       base::Bind(&TransportConnectJob::OnIOComplete, base::Unretained(this)),
@@ -170,6 +172,11 @@ int TransportConnectJob::DoResolveHost() {
 }
 
 int TransportConnectJob::DoResolveHostComplete(int result) {
+  connect_timing_.dns_end = base::TimeTicks::Now();
+  // Overwrite connection start time, since for connections that do not go
+  // through proxies, |connect_start| should not include dns lookup time.
+  connect_timing_.connect_start = connect_timing_.dns_end;
+
   if (result == OK) {
     // Invoke callback, and abort if it fails.
     if (!params_->host_resolution_callback().is_null())
@@ -185,7 +192,6 @@ int TransportConnectJob::DoTransportConnect() {
   next_state_ = STATE_TRANSPORT_CONNECT_COMPLETE;
   transport_socket_.reset(client_socket_factory_->CreateTransportClientSocket(
         addresses_, net_log().net_log(), net_log().source()));
-  connect_start_time_ = base::TimeTicks::Now();
   int rv = transport_socket_->Connect(
       base::Bind(&TransportConnectJob::OnIOComplete, base::Unretained(this)));
   if (rv == ERR_IO_PENDING &&
@@ -201,10 +207,10 @@ int TransportConnectJob::DoTransportConnect() {
 int TransportConnectJob::DoTransportConnectComplete(int result) {
   if (result == OK) {
     bool is_ipv4 = addresses_.front().GetFamily() == ADDRESS_FAMILY_IPV4;
-    DCHECK(connect_start_time_ != base::TimeTicks());
-    DCHECK(start_time_ != base::TimeTicks());
+    DCHECK(!connect_timing_.connect_start.is_null());
+    DCHECK(!connect_timing_.dns_start.is_null());
     base::TimeTicks now = base::TimeTicks::Now();
-    base::TimeDelta total_duration = now - start_time_;
+    base::TimeDelta total_duration = now - connect_timing_.dns_start;
     UMA_HISTOGRAM_CUSTOM_TIMES(
         "Net.DNS_Resolution_And_TCP_Connection_Latency2",
         total_duration,
@@ -212,7 +218,7 @@ int TransportConnectJob::DoTransportConnectComplete(int result) {
         base::TimeDelta::FromMinutes(10),
         100);
 
-    base::TimeDelta connect_duration = now - connect_start_time_;
+    base::TimeDelta connect_duration = now - connect_timing_.connect_start;
     UMA_HISTOGRAM_CUSTOM_TIMES("Net.TCP_Connection_Latency",
         connect_duration,
         base::TimeDelta::FromMilliseconds(1),
@@ -288,10 +294,10 @@ void TransportConnectJob::DoIPv6FallbackTransportConnectComplete(int result) {
   DCHECK(fallback_addresses_.get());
 
   if (result == OK) {
-    DCHECK(fallback_connect_start_time_ != base::TimeTicks());
-    DCHECK(start_time_ != base::TimeTicks());
+    DCHECK(!fallback_connect_start_time_.is_null());
+    DCHECK(!connect_timing_.dns_start.is_null());
     base::TimeTicks now = base::TimeTicks::Now();
-    base::TimeDelta total_duration = now - start_time_;
+    base::TimeDelta total_duration = now - connect_timing_.dns_start;
     UMA_HISTOGRAM_CUSTOM_TIMES(
         "Net.DNS_Resolution_And_TCP_Connection_Latency2",
         total_duration,
@@ -324,7 +330,6 @@ void TransportConnectJob::DoIPv6FallbackTransportConnectComplete(int result) {
 
 int TransportConnectJob::ConnectInternal() {
   next_state_ = STATE_RESOLVE_HOST;
-  start_time_ = base::TimeTicks::Now();
   return DoLoop(OK);
 }
 

net/socket/transport_client_socket_pool.h

@@ -120,12 +120,6 @@ class NET_EXPORT_PRIVATE TransportConnectJob : public ConnectJob {
   AddressList addresses_;
   State next_state_;
 
-  // The time Connect() was called.
-  base::TimeTicks start_time_;
-
-  // The time the connect was started (after DNS finished).
-  base::TimeTicks connect_start_time_;
-
   scoped_ptr<StreamSocket> transport_socket_;
 
   scoped_ptr<StreamSocket> fallback_transport_socket_;

net/socket/transport_client_socket_pool_unittest.cc

@@ -11,7 +11,9 @@
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/threading/platform_thread.h"
+#include "net/base/capturing_net_log.h"
 #include "net/base/ip_endpoint.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_util.h"
@@ -33,6 +35,62 @@ const int kMaxSockets = 32;
 const int kMaxSocketsPerGroup = 6;
 const net::RequestPriority kDefaultPriority = LOW;
 
+// Make sure |handle| sets load times correctly when it has been assigned a
+// reused socket.
+void TestLoadTimingInfoConnectedReused(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  // Only pass true in as |is_reused|, as in general, HttpStream types should
+  // have stricter concepts of reuse than socket pools.
+  EXPECT_TRUE(handle.GetLoadTimingInfo(true, &load_timing_info));
+
+  EXPECT_TRUE(load_timing_info.socket_reused);
+  EXPECT_NE(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.connect_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.connect_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
+// Make sure |handle| sets load times correctly when it has been assigned a
+// fresh socket.  Also runs TestLoadTimingInfoConnectedReused, since the owner
+// of a connection where |is_reused| is false may consider the connection
+// reused.
+void TestLoadTimingInfoConnectedNotReused(const ClientSocketHandle& handle) {
+  EXPECT_FALSE(handle.is_reused());
+
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  EXPECT_NE(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.dns_start,
+            load_timing_info.connect_timing.dns_end);
+  EXPECT_LE(load_timing_info.connect_timing.dns_end,
+            load_timing_info.connect_timing.connect_start);
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.connect_end);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+
+  TestLoadTimingInfoConnectedReused(handle);
+}
+
 void SetIPv4Address(IPEndPoint* address) {
   IPAddressNumber number;
   CHECK(ParseIPLiteralToNumber("1.1.1.1", &number));
@@ -47,9 +105,11 @@ void SetIPv6Address(IPEndPoint* address) {
 
 class MockClientSocket : public StreamSocket {
  public:
-  MockClientSocket(const AddressList& addrlist)
+  MockClientSocket(const AddressList& addrlist, net::NetLog* net_log)
       : connected_(false),
-        addrlist_(addrlist) {}
+        addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
@@ -119,7 +179,10 @@ class MockClientSocket : public StreamSocket {
 
 class MockFailingClientSocket : public StreamSocket {
  public:
-  MockFailingClientSocket(const AddressList& addrlist) : addrlist_(addrlist) {}
+  MockFailingClientSocket(const AddressList& addrlist, net::NetLog* net_log)
+      : addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
@@ -190,13 +253,16 @@ class MockPendingClientSocket : public StreamSocket {
       const AddressList& addrlist,
       bool should_connect,
       bool should_stall,
-      base::TimeDelta delay)
+      base::TimeDelta delay,
+      net::NetLog* net_log)
       : ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
         should_connect_(should_connect),
         should_stall_(should_stall),
         delay_(delay),
         is_connected_(false),
-        addrlist_(addrlist) {}
+        addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
@@ -299,10 +365,10 @@ class MockClientSocketFactory : public ClientSocketFactory {
     MOCK_STALLED_CLIENT_SOCKET,
   };
 
-  MockClientSocketFactory()
-      : allocation_count_(0), client_socket_type_(MOCK_CLIENT_SOCKET),
-        client_socket_types_(NULL), client_socket_index_(0),
-        client_socket_index_max_(0),
+  explicit MockClientSocketFactory(NetLog* net_log)
+      : net_log_(net_log), allocation_count_(0),
+        client_socket_type_(MOCK_CLIENT_SOCKET), client_socket_types_(NULL),
+        client_socket_index_(0), client_socket_index_max_(0),
         delay_(base::TimeDelta::FromMilliseconds(
             ClientSocketPool::kMaxConnectRetryIntervalMs)) {}
 
@@ -329,23 +395,24 @@ class MockClientSocketFactory : public ClientSocketFactory {
 
     switch (type) {
       case MOCK_CLIENT_SOCKET:
-        return new MockClientSocket(addresses);
+        return new MockClientSocket(addresses, net_log_);
       case MOCK_FAILING_CLIENT_SOCKET:
-        return new MockFailingClientSocket(addresses);
+        return new MockFailingClientSocket(addresses, net_log_);
       case MOCK_PENDING_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, true, false, base::TimeDelta());
+            addresses, true, false, base::TimeDelta(), net_log_);
       case MOCK_PENDING_FAILING_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, false, false, base::TimeDelta());
+            addresses, false, false, base::TimeDelta(), net_log_);
       case MOCK_DELAYED_CLIENT_SOCKET:
-        return new MockPendingClientSocket(addresses, true, false, delay_);
+        return new MockPendingClientSocket(
+            addresses, true, false, delay_, net_log_);
       case MOCK_STALLED_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, true, true, base::TimeDelta());
+            addresses, true, true, base::TimeDelta(), net_log_);
       default:
         NOTREACHED();
-        return new MockClientSocket(addresses);
+        return new MockClientSocket(addresses, net_log_);
     }
   }
 
@@ -380,6 +447,7 @@ class MockClientSocketFactory : public ClientSocketFactory {
   void set_delay(base::TimeDelta delay) { delay_ = delay; }
 
  private:
+  NetLog* net_log_;
   int allocation_count_;
   ClientSocketType client_socket_type_;
   ClientSocketType* client_socket_types_;
@@ -403,6 +471,7 @@ class TransportClientSocketPoolTest : public testing::Test {
                                       OnHostResolutionCallback())),
         histograms_(new ClientSocketPoolHistograms("TCPUnitTest")),
         host_resolver_(new MockHostResolver),
+        client_socket_factory_(&net_log_),
         pool_(kMaxSockets,
               kMaxSocketsPerGroup,
               histograms_.get(),
@@ -440,6 +509,7 @@ class TransportClientSocketPoolTest : public testing::Test {
   size_t completion_count() const { return test_base_.completion_count(); }
 
   bool connect_backup_jobs_enabled_;
+  CapturingNetLog net_log_;
   scoped_refptr<TransportSocketParams> params_;
   scoped_refptr<TransportSocketParams> low_params_;
   scoped_ptr<ClientSocketPoolHistograms> histograms_;
@@ -532,8 +602,7 @@ TEST_F(TransportClientSocketPoolTest, Basic) {
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
-
-  handle.Reset();
+  TestLoadTimingInfoConnectedNotReused(handle);
 }
 
 TEST_F(TransportClientSocketPoolTest, InitHostResolutionFailure) {
@@ -899,6 +968,34 @@ TEST_F(TransportClientSocketPoolTest, FailingActiveRequestWithPendingRequests) {
     EXPECT_EQ(ERR_CONNECTION_FAILED, (*requests())[i]->WaitForResult());
 }
 
+TEST_F(TransportClientSocketPoolTest, IdleSocketLoadTiming) {
+  TestCompletionCallback callback;
+  ClientSocketHandle handle;
+  int rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
+                       BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_FALSE(handle.is_initialized());
+  EXPECT_FALSE(handle.socket());
+
+  EXPECT_EQ(OK, callback.WaitForResult());
+  EXPECT_TRUE(handle.is_initialized());
+  EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoConnectedNotReused(handle);
+
+  handle.Reset();
+  // Need to run all pending to release the socket back to the pool.
+  MessageLoop::current()->RunUntilIdle();
+
+  // Now we should have 1 idle socket.
+  EXPECT_EQ(1, pool_.IdleSocketCount());
+
+  rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
+                   BoundNetLog());
+  EXPECT_EQ(OK, rv);
+  EXPECT_EQ(0, pool_.IdleSocketCount());
+  TestLoadTimingInfoConnectedReused(handle);
+}
+
 TEST_F(TransportClientSocketPoolTest, ResetIdleSocketsOnIPAddressChange) {
   TestCompletionCallback callback;
   ClientSocketHandle handle;