summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authormmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2013-01-07 23:17:48 +0000
committermmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98>2013-01-07 23:17:48 +0000
commit034df0f31b28222fd689600695edbdc2de66f626 (patch)
tree3e75d5fea71352d84fb33f93d4a3249248bc6704
parent7f39bb69692953a1085bd2ac7eb8eb53ecf5f46a (diff)
downloadchromium_src-034df0f31b28222fd689600695edbdc2de66f626.zip
chromium_src-034df0f31b28222fd689600695edbdc2de66f626.tar.gz
chromium_src-034df0f31b28222fd689600695edbdc2de66f626.tar.bz2
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
-rw-r--r--net/base/load_timing_info.cc22
-rw-r--r--net/base/load_timing_info.h109
-rw-r--r--net/net.gyp2
-rw-r--r--net/socket/client_socket_handle.cc19
-rw-r--r--net/socket/client_socket_handle.h18
-rw-r--r--net/socket/client_socket_pool_base.cc28
-rw-r--r--net/socket/client_socket_pool_base.h9
-rw-r--r--net/socket/client_socket_pool_base_unittest.cc149
-rw-r--r--net/socket/socket_test_util.cc11
-rw-r--r--net/socket/socks_client_socket_pool_unittest.cc30
-rw-r--r--net/socket/ssl_client_socket_pool.cc25
-rw-r--r--net/socket/ssl_client_socket_pool.h3
-rw-r--r--net/socket/ssl_client_socket_pool_unittest.cc75
-rw-r--r--net/socket/transport_client_socket_pool.cc23
-rw-r--r--net/socket/transport_client_socket_pool.h6
-rw-r--r--net/socket/transport_client_socket_pool_unittest.cc133
16 files changed, 606 insertions, 56 deletions
diff --git a/net/base/load_timing_info.cc b/net/base/load_timing_info.cc
new file mode 100644
index 0000000..ab5b750
--- /dev/null
+++ b/net/base/load_timing_info.cc
@@ -0,0 +1,22 @@
+// 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
+
diff --git a/net/base/load_timing_info.h b/net/base/load_timing_info.h
new file mode 100644
index 0000000..446b1e9
--- /dev/null
+++ b/net/base/load_timing_info.h
@@ -0,0 +1,109 @@
+// 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_
diff --git a/net/net.gyp b/net/net.gyp
index aa6aaf9..d2d9a7f 100644
--- a/net/net.gyp
+++ b/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',
diff --git a/net/socket/client_socket_handle.cc b/net/socket/client_socket_handle.cc
index 20ab672..32703da 100644
--- a/net/socket/client_socket_handle.cc
+++ b/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();
diff --git a/net/socket/client_socket_handle.h b/net/socket/client_socket_handle.h
index 8da5d49..6a6a189 100644
--- a/net/socket/client_socket_handle.h
+++ b/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);
};
diff --git a/net/socket/client_socket_pool_base.cc b/net/socket/client_socket_pool_base.cc
index 1c12412..7a02909 100644
--- a/net/socket/client_socket_pool_base.cc
+++ b/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(
diff --git a/net/socket/client_socket_pool_base.h b/net/socket/client_socket_pool_base.h
index 39dbeb0..75cc1ac 100644
--- a/net/socket/client_socket_pool_base.h
+++ b/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,
diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc
index f55dadb..d966e3e 100644
--- a/net/socket/client_socket_pool_base_unittest.cc
+++ b/net/socket/client_socket_pool_base_unittest.cc
@@ -14,10 +14,12 @@
#include "base/memory/scoped_vector.h"
#include "base/memory/weak_ptr.h"
#include "base/message_loop.h"
+#include "base/run_loop.h"
#include "base/stringprintf.h"
#include "base/string_number_conversions.h"
#include "base/threading/platform_thread.h"
#include "base/values.h"
+#include "net/base/load_timing_info.h"
#include "net/base/net_errors.h"
#include "net/base/net_log.h"
#include "net/base/net_log_unittest.h"
@@ -43,6 +45,84 @@ const int kDefaultMaxSockets = 4;
const int kDefaultMaxSocketsPerGroup = 2;
const net::RequestPriority kDefaultPriority = MEDIUM;
+// 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_EQ(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.connect_start.is_null());
+ EXPECT_LE(load_timing_info.connect_timing.connect_start,
+ load_timing_info.connect_timing.connect_end);
+ 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());
+
+ TestLoadTimingInfoConnectedReused(handle);
+}
+
+// Make sure |handle| sets load times correctly, in the case that it does not
+// currently have a socket.
+void TestLoadTimingInfoNotConnected(const ClientSocketHandle& handle) {
+ // Should only be set to true once a socket is assigned, if at all.
+ EXPECT_FALSE(handle.is_reused());
+
+ LoadTimingInfo load_timing_info;
+ EXPECT_FALSE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+ EXPECT_FALSE(load_timing_info.socket_reused);
+ EXPECT_EQ(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());
+}
+
class TestSocketParams : public base::RefCounted<TestSocketParams> {
public:
TestSocketParams() : ignore_limits_(false) {}
@@ -62,8 +142,12 @@ typedef ClientSocketPoolBase<TestSocketParams> TestClientSocketPoolBase;
class MockClientSocket : public StreamSocket {
public:
- MockClientSocket() : connected_(false), was_used_to_convey_data_(false),
- num_bytes_read_(0) {}
+ explicit MockClientSocket(net::NetLog* net_log)
+ : connected_(false),
+ net_log_(BoundNetLog::Make(net_log, net::NetLog::SOURCE_SOCKET)),
+ was_used_to_convey_data_(false),
+ num_bytes_read_(0) {
+ }
// Socket implementation.
virtual int Read(
@@ -238,7 +322,7 @@ class TestConnectJob : public ConnectJob {
AddressList ignored;
client_socket_factory_->CreateTransportClientSocket(
ignored, NULL, net::NetLog::Source());
- set_socket(new MockClientSocket());
+ set_socket(new MockClientSocket(net_log().net_log()));
switch (job_type_) {
case kMockJob:
return DoConnect(true /* successful */, false /* sync */,
@@ -373,10 +457,13 @@ class TestConnectJob : public ConnectJob {
class TestConnectJobFactory
: public TestClientSocketPoolBase::ConnectJobFactory {
public:
- explicit TestConnectJobFactory(MockClientSocketFactory* client_socket_factory)
+ TestConnectJobFactory(MockClientSocketFactory* client_socket_factory,
+ NetLog* net_log)
: job_type_(TestConnectJob::kMockJob),
job_types_(NULL),
- client_socket_factory_(client_socket_factory) {}
+ client_socket_factory_(client_socket_factory),
+ net_log_(net_log) {
+}
virtual ~TestConnectJobFactory() {}
@@ -409,7 +496,7 @@ class TestConnectJobFactory
timeout_duration_,
delegate,
client_socket_factory_,
- NULL);
+ net_log_);
}
virtual base::TimeDelta ConnectionTimeout() const {
@@ -421,6 +508,7 @@ class TestConnectJobFactory
std::list<TestConnectJob::JobType>* job_types_;
base::TimeDelta timeout_duration_;
MockClientSocketFactory* const client_socket_factory_;
+ NetLog* net_log_;
DISALLOW_COPY_AND_ASSIGN(TestConnectJobFactory);
};
@@ -638,7 +726,8 @@ class ClientSocketPoolBaseTest : public testing::Test {
base::TimeDelta unused_idle_socket_timeout,
base::TimeDelta used_idle_socket_timeout) {
DCHECK(!pool_.get());
- connect_job_factory_ = new TestConnectJobFactory(&client_socket_factory_);
+ connect_job_factory_ = new TestConnectJobFactory(&client_socket_factory_,
+ &net_log_);
pool_.reset(new TestClientSocketPool(max_sockets,
max_sockets_per_group,
&histograms_,
@@ -671,6 +760,7 @@ class ClientSocketPoolBaseTest : public testing::Test {
ScopedVector<TestSocketRequest>* requests() { return test_base_.requests(); }
size_t completion_count() const { return test_base_.completion_count(); }
+ CapturingNetLog net_log_;
bool connect_backup_jobs_enabled_;
bool cleanup_timer_enabled_;
MockClientSocketFactory client_socket_factory_;
@@ -814,6 +904,7 @@ TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
TestCompletionCallback callback;
ClientSocketHandle handle;
CapturingBoundNetLog log;
+ TestLoadTimingInfoNotConnected(handle);
EXPECT_EQ(OK,
handle.Init("a",
@@ -824,7 +915,10 @@ TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
log.bound()));
EXPECT_TRUE(handle.is_initialized());
EXPECT_TRUE(handle.socket());
+ TestLoadTimingInfoConnectedNotReused(handle);
+
handle.Reset();
+ TestLoadTimingInfoNotConnected(handle);
CapturingNetLog::CapturedEntryList entries;
log.GetEntries(&entries);
@@ -865,6 +959,7 @@ TEST_F(ClientSocketPoolBaseTest, InitConnectionFailure) {
EXPECT_FALSE(handle.socket());
EXPECT_FALSE(handle.is_ssl_error());
EXPECT_TRUE(handle.ssl_error_response_info().headers.get() == NULL);
+ TestLoadTimingInfoNotConnected(handle);
CapturingNetLog::CapturedEntryList entries;
log.GetEntries(&entries);
@@ -1634,6 +1729,7 @@ TEST_F(ClientSocketPoolBaseTest, CancelActiveRequestThenRequestSocket) {
EXPECT_EQ(OK, callback.WaitForResult());
EXPECT_FALSE(handle.is_reused());
+ TestLoadTimingInfoConnectedNotReused(handle);
EXPECT_EQ(2, client_socket_factory_.allocation_count());
}
@@ -1688,10 +1784,15 @@ TEST_F(ClientSocketPoolBaseTest, BasicAsynchronous) {
log.bound());
EXPECT_EQ(ERR_IO_PENDING, rv);
EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", &handle));
+ TestLoadTimingInfoNotConnected(handle);
+
EXPECT_EQ(OK, callback.WaitForResult());
EXPECT_TRUE(handle.is_initialized());
EXPECT_TRUE(handle.socket());
+ TestLoadTimingInfoConnectedNotReused(handle);
+
handle.Reset();
+ TestLoadTimingInfoNotConnected(handle);
CapturingNetLog::CapturedEntryList entries;
log.GetEntries(&entries);
@@ -2044,6 +2145,7 @@ TEST_F(ClientSocketPoolBaseTest, DisableCleanupTimerReuse) {
// Use and release the socket.
EXPECT_EQ(1, handle.socket()->Write(NULL, 1, CompletionCallback()));
+ TestLoadTimingInfoConnectedNotReused(handle);
handle.Reset();
// Should now have one idle socket.
@@ -2060,6 +2162,7 @@ TEST_F(ClientSocketPoolBaseTest, DisableCleanupTimerReuse) {
log.bound());
ASSERT_EQ(OK, rv);
EXPECT_TRUE(handle.is_reused());
+ TestLoadTimingInfoConnectedReused(handle);
ASSERT_TRUE(pool_->HasGroup("a"));
EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
@@ -3383,11 +3486,43 @@ TEST_F(ClientSocketPoolBaseTest, PreconnectJobsTakenByNormalRequests) {
ASSERT_EQ(OK, callback1.WaitForResult());
+ // Make sure if a preconneced socket is not fully connected when a request
+ // starts, it has a connect start time.
+ TestLoadTimingInfoConnectedNotReused(handle1);
handle1.Reset();
EXPECT_EQ(1, pool_->IdleSocketCountInGroup("a"));
}
+// Checks that fully connected preconnect jobs have no connect times, and are
+// marked as reused.
+TEST_F(ClientSocketPoolBaseTest, ConnectedPreconnectJobsHaveNoConnectTimes) {
+ CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
+ connect_job_factory_->set_job_type(TestConnectJob::kMockJob);
+ pool_->RequestSockets("a", &params_, 1, BoundNetLog());
+
+ ASSERT_TRUE(pool_->HasGroup("a"));
+ EXPECT_EQ(0, pool_->NumConnectJobsInGroup("a"));
+ EXPECT_EQ(0, pool_->NumUnassignedConnectJobsInGroup("a"));
+ EXPECT_EQ(1, pool_->IdleSocketCountInGroup("a"));
+
+ ClientSocketHandle handle;
+ TestCompletionCallback callback;
+ EXPECT_EQ(OK, handle.Init("a",
+ params_,
+ kDefaultPriority,
+ callback.callback(),
+ pool_.get(),
+ BoundNetLog()));
+
+ // Make sure the idle socket was used.
+ EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
+
+ TestLoadTimingInfoConnectedReused(handle);
+ handle.Reset();
+ TestLoadTimingInfoNotConnected(handle);
+}
+
// http://crbug.com/64940 regression test.
TEST_F(ClientSocketPoolBaseTest, PreconnectClosesIdleSocketRemovesGroup) {
const int kMaxTotalSockets = 3;
diff --git a/net/socket/socket_test_util.cc b/net/socket/socket_test_util.cc
index 590a56d..6b0070b 100644
--- a/net/socket/socket_test_util.cc
+++ b/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();
}
diff --git a/net/socket/socks_client_socket_pool_unittest.cc b/net/socket/socks_client_socket_pool_unittest.cc
index a8d0a9f..e69a297 100644
--- a/net/socket/socks_client_socket_pool_unittest.cc
+++ b/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) {
diff --git a/net/socket/ssl_client_socket_pool.cc b/net/socket/ssl_client_socket_pool.cc
index 30ad46e..826ccc8 100644
--- a/net/socket/ssl_client_socket_pool.cc
+++ b/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,
diff --git a/net/socket/ssl_client_socket_pool.h b/net/socket/ssl_client_socket_pool.h
index 6ee0155..03f79dc 100644
--- a/net/socket/ssl_client_socket_pool.h
+++ b/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);
diff --git a/net/socket/ssl_client_socket_pool_unittest.cc b/net/socket/ssl_client_socket_pool_unittest.cc
index 92f0ce65..0a8b87a 100644
--- a/net/socket/ssl_client_socket_pool_unittest.cc
+++ b/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) {
diff --git a/net/socket/transport_client_socket_pool.cc b/net/socket/transport_client_socket_pool.cc
index 84e89c8..ae394f5 100644
--- a/net/socket/transport_client_socket_pool.cc
+++ b/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);
}
diff --git a/net/socket/transport_client_socket_pool.h b/net/socket/transport_client_socket_pool.h
index af14152..2a1053c 100644
--- a/net/socket/transport_client_socket_pool.h
+++ b/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_;
diff --git a/net/socket/transport_client_socket_pool_unittest.cc b/net/socket/transport_client_socket_pool_unittest.cc
index aefe79c..61a10e1 100644
--- a/net/socket/transport_client_socket_pool_unittest.cc
+++ b/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;