diff options
author | mmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2013-01-07 23:17:48 +0000 |
---|---|---|
committer | mmenke@chromium.org <mmenke@chromium.org@0039d316-1c4b-4281-b951-d872f2087c98> | 2013-01-07 23:17:48 +0000 |
commit | 034df0f31b28222fd689600695edbdc2de66f626 (patch) | |
tree | 3e75d5fea71352d84fb33f93d4a3249248bc6704 | |
parent | 7f39bb69692953a1085bd2ac7eb8eb53ecf5f46a (diff) | |
download | chromium_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.cc | 22 | ||||
-rw-r--r-- | net/base/load_timing_info.h | 109 | ||||
-rw-r--r-- | net/net.gyp | 2 | ||||
-rw-r--r-- | net/socket/client_socket_handle.cc | 19 | ||||
-rw-r--r-- | net/socket/client_socket_handle.h | 18 | ||||
-rw-r--r-- | net/socket/client_socket_pool_base.cc | 28 | ||||
-rw-r--r-- | net/socket/client_socket_pool_base.h | 9 | ||||
-rw-r--r-- | net/socket/client_socket_pool_base_unittest.cc | 149 | ||||
-rw-r--r-- | net/socket/socket_test_util.cc | 11 | ||||
-rw-r--r-- | net/socket/socks_client_socket_pool_unittest.cc | 30 | ||||
-rw-r--r-- | net/socket/ssl_client_socket_pool.cc | 25 | ||||
-rw-r--r-- | net/socket/ssl_client_socket_pool.h | 3 | ||||
-rw-r--r-- | net/socket/ssl_client_socket_pool_unittest.cc | 75 | ||||
-rw-r--r-- | net/socket/transport_client_socket_pool.cc | 23 | ||||
-rw-r--r-- | net/socket/transport_client_socket_pool.h | 6 | ||||
-rw-r--r-- | net/socket/transport_client_socket_pool_unittest.cc | 133 |
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", ¶ms_, 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; |