LoadTiming implementation in net, part 1.

LoadTiming implementation in net, part 1.

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

BUG=77446
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=175412

[mmenke, 2012-12-14 01:15:18]

I'm thinking of landing this in 4 parts:

1)  Log times it takes to connect and store them in the ConnectHandle (This CL).
2)  All other times, and URLRequest function to access them.
3)  Hook it up and get rid of LoadTimingObserver.
4)  Do something better in the SPDY proxy case.  First pass, we'll be returning
somewhat weird socket IDs, though connection times should be fine.  Still not
sure what I'll do here.

For reviewing this CL, I suggest looking at the new files first, then
client_socket_handle, then client_socket_pool_base, followed by
transport_client_socket_pool, and then ssl_client_socket_pool (And then the
tests).

https://codereview.chromium.org/11428150/diff/56034/net/base/load_timing_info.h
File net/base/load_timing_info.h (right):

https://codereview.chromium.org/11428150/diff/56034/net/base/load_timing_info...
net/base/load_timing_info.h:50: base::Time request_start_time;
This could be taken care of by the caller, but we record the time at the same
place at request_start, anyways, so seemed reasonable to include it.

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
File net/socket/client_socket_handle.cc (right):

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
net/socket/client_socket_handle.cc:66: connect_timing_ = ConnectTiming();
This will result in a URLRequest not giving correct times after it's called
Reset.  This happens in the Connection:Close case, and maybe on some errors.

Fortunately, the only places we read the load timing are in two delegate
functions:  OnResponseStarted and OnResponseRedirected, so that's not an issue
for the current use case.  Can add a workaround for this if we ever need it.

[eroman, 2012-12-14 04:08:34]

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
File net/socket/client_socket_handle.cc (right):

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
net/socket/client_socket_handle.cc:66: connect_timing_ = ConnectTiming();
On 2012/12/14 01:15:18, Matt Menke wrote:
> This will result in a URLRequest not giving correct times after it's called
> Reset.  This happens in the Connection:Close case, and maybe on some errors.
> 
> Fortunately, the only places we read the load timing are in two delegate
> functions:  OnResponseStarted and OnResponseRedirected, so that's not an issue
> for the current use case.  Can add a workaround for this if we ever need it.

I suggest additionally dumping these timings into NetLog. They could be useful
for slow request debugging. Also hung requests (although hung requests are
likely in connection establishment, and hence before this has been filled).

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info.h
File net/base/load_timing_info.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:5: #ifndef LOAD_TIMING_INFO_H_
Shouldn't this be NET_BASE_LOAD_TIMING_INFO_H_ ?

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:30: // Due to preconnect, late-binding, and
cancelled requests, a request may use a
I found this paragraph challenging to read. Not sure I understood it.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:50: base::Time request_start_time;
Why is this a Time whereas the rest are TimeTicks?

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:54: base::TimeTicks proxy_start;
Nit: I would suggest calling this proxy_resolve_start instead, so it is not
confused with the time spent connecting to the proxy.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:58: // used proxies to look up the DNS address. 
Also NULL for SOCKS4 proxies,
Seems we *could* include this for SOCKS4. If needed, we could do the DNS resolve
first (in fact seems desirable to do that). No action necessary for this CL.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:65: // proxy DNS lookup times, blocking, TCP, TCP
retries and SSL time.
Is this what webtiming expects too? (I could see how proxy DNS might fit into
proxy_start/proxy_end instead).

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base.cc:864: ConnectTiming connect_timing =
job->connect_timing();
Could you add a comment above these 2 lines, mentioning that we make copies of
the data because |job| might be subsequently deleted?

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base.h:108: ConnectTiming& connect_timing() {
return connect_timing_; }
Please make it return a const-reference instead. I don't think there is need for
a mutable getter.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:48: // Make sure |handle| sets
load times are set correctly when it has been
This reads weird, i think there is a "set" too many.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:72: // Make sure |handle| sets
load times are set correctly when it has been
same comment as earlier.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:74: // the own of a connection
where |is_reused| is false may consider the
typo? "the own of a connection"

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:3517: // Make sure thee idle
socket was used.
thee --> the; unless thou wants to sound pompous.

https://codereview.chromium.org/11428150/diff/47038/net/socket/connect_timing.h
File net/socket/connect_timing.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/connect_timing...
net/socket/connect_timing.h:5: #ifndef CONNECT_TIMING_H_
I believe this should be a full path not just file name.

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
File net/socket/ssl_client_socket_pool.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool.cc:271: connect_timing().dns_end =
socket_connect_timing.dns_end;
can you access it directly instead? (i.e. make the field protected or
something).

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool.cc:319: DCHECK(connect_timing().ssl_start !=
base::TimeTicks());
!x.is_null() ?

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
File net/socket/ssl_client_socket_pool_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool_unittest.cc:69: // Just like
TestLoadTimingInfo, except DNS times are expected to be NULL, for
I don't like calling times "NULL". I think it would be clearer maybe as
lowercase null, since it is a different nullity concept.

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
File net/socket/transport_client_socket_pool.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool.cc:210:
DCHECK(connect_timing().connect_start != base::TimeTicks());
might want to test is_null() throughout for consistency.

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
File net/socket/transport_client_socket_pool_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:38: // Make sure |handle|
sets load times are set correctly when it has been
weird

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:62: // Make sure |handle|
sets load times are set correctly when it has been
weird

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:64: // the own of a
connection where |is_reused| is false may consider the
weird

[mmenke, 2012-12-14 13:36:12]

Thanks for the feedback!

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
File net/socket/client_socket_handle.cc (right):

https://codereview.chromium.org/11428150/diff/56034/net/socket/client_socket_...
net/socket/client_socket_handle.cc:66: connect_timing_ = ConnectTiming();
On 2012/12/14 04:08:34, eroman wrote:
> On 2012/12/14 01:15:18, Matt Menke wrote:
> > This will result in a URLRequest not giving correct times after it's called
> > Reset.  This happens in the Connection:Close case, and maybe on some errors.
> > 
> > Fortunately, the only places we read the load timing are in two delegate
> > functions:  OnResponseStarted and OnResponseRedirected, so that's not an
issue
> > for the current use case.  Can add a workaround for this if we ever need it.
> 
> I suggest additionally dumping these timings into NetLog. They could be useful
> for slow request debugging. Also hung requests (although hung requests are
> likely in connection establishment, and hence before this has been filled).

Where are you thinking of dumping them?  With in-progress URLRequests when
net-internals is opened?  That sounds reasonable.

We could also have logging for in-progress ConnectJobs, though hooking that up
would be a little tricky.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info.h
File net/base/load_timing_info.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:5: #ifndef LOAD_TIMING_INFO_H_
On 2012/12/14 04:08:35, eroman wrote:
> Shouldn't this be NET_BASE_LOAD_TIMING_INFO_H_ ?

Done.  Odd that the linter didn't catch this.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:30: // Due to preconnect, late-binding, and
cancelled requests, a request may use a
On 2012/12/14 04:08:35, eroman wrote:
> I found this paragraph challenging to read. Not sure I understood it.

I've tried to make it easier to understand, but it's rather complicated.

Basically, the non-starred times are computed in a guaranteed order by objects
created and owned by the URLRequest.  The starred times are computed by the
ConnectJob.  A URLRequest may be assigned a ClientSocketHandle created by a
ConnectJob that started before the URLRequest started, or while it was resolving
the proxy.  The ConnectJob it ends up getting a socket from could have been that
for another, lower priority, request, or that for a preconnect.

We could modify the times so there is a guaranteed ordering (And in fact, we may
well want to do that, before passing the data to WebKit), but not sure we should
be doing that in the network stack.  It's also not clear how we should be doing
this - we could just chop off dns / connect / ssl times that occur too early,
but proxy times are reported by the NavigationTiming API, so it may make more
sense to modify the proxy times instead, and then clip the others by
request_start.

Since choices here are based more on WebKit/NavigationTiming API behavior, think
they make more sense in chrome/ than they do here.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:50: base::Time request_start_time;
On 2012/12/14 04:08:35, eroman wrote:
> Why is this a Time whereas the rest are TimeTicks?

Added a comment.  This is the same thing LoadTimingObserver does - all times are
recorded in TimeTicks, so that the deltas aren't affected by clock changes, but
the underlying API wants real times, so need a base::Time to convert TimeTicks
to times.

We could get rid of this field, and let the consumer worry about it all, but we
already record the Time we send a request, and it has to be a Time, since we
save it in the cache for expiration logic, so seemed reasonable to store it
here.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:54: base::TimeTicks proxy_start;
On 2012/12/14 04:08:35, eroman wrote:
> Nit: I would suggest calling this proxy_resolve_start instead, so it is not
> confused with the time spent connecting to the proxy.

SGTM.  Done.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:58: // used proxies to look up the DNS address. 
Also NULL for SOCKS4 proxies,
On 2012/12/14 04:08:35, eroman wrote:
> Seems we *could* include this for SOCKS4. If needed, we could do the DNS
resolve
> first (in fact seems desirable to do that). No action necessary for this CL.

Sounds reasonable to me.  Looked to me like it would require a fair bit of
refactoring, though I didn't spend much time investigating.

https://codereview.chromium.org/11428150/diff/47038/net/base/load_timing_info...
net/base/load_timing_info.h:65: // proxy DNS lookup times, blocking, TCP, TCP
retries and SSL time.
On 2012/12/14 04:08:35, eroman wrote:
> Is this what webtiming expects too? (I could see how proxy DNS might fit into
> proxy_start/proxy_end instead).

The spec is unclear.  I talked to one of the NavigationTiming API authors (Who
conveniently works at Google), and this is the behavior he suggested.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base.cc:864: ConnectTiming connect_timing =
job->connect_timing();
On 2012/12/14 04:08:35, eroman wrote:
> Could you add a comment above these 2 lines, mentioning that we make copies of
> the data because |job| might be subsequently deleted?

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base.h:108: ConnectTiming& connect_timing() {
return connect_timing_; }
On 2012/12/14 04:08:35, eroman wrote:
> Please make it return a const-reference instead. I don't think there is need
for
> a mutable getter.

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
File net/socket/client_socket_pool_base_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:48: // Make sure |handle| sets
load times are set correctly when it has been
On 2012/12/14 04:08:35, eroman wrote:
> This reads weird, i think there is a "set" too many.

Done.  I should know by now to vet all my last minute comment changes before
sending out code for a review.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:72: // Make sure |handle| sets
load times are set correctly when it has been
On 2012/12/14 04:08:35, eroman wrote:
> same comment as earlier.

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:74: // the own of a connection
where |is_reused| is false may consider the
On 2012/12/14 04:08:35, eroman wrote:
> typo? "the own of a connection"

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/client_socket_...
net/socket/client_socket_pool_base_unittest.cc:3517: // Make sure thee idle
socket was used.
On 2012/12/14 04:08:35, eroman wrote:
> thee --> the; unless thou wants to sound pompous.

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/connect_timing.h
File net/socket/connect_timing.h (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/connect_timing...
net/socket/connect_timing.h:5: #ifndef CONNECT_TIMING_H_
On 2012/12/14 04:08:35, eroman wrote:
> I believe this should be a full path not just file name.

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
File net/socket/ssl_client_socket_pool.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool.cc:271: connect_timing().dns_end =
socket_connect_timing.dns_end;
On 2012/12/14 04:08:35, eroman wrote:
> can you access it directly instead? (i.e. make the field protected or
> something).

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool.cc:319: DCHECK(connect_timing().ssl_start !=
base::TimeTicks());
On 2012/12/14 04:08:35, eroman wrote:
> !x.is_null() ?

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
File net/socket/ssl_client_socket_pool_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/ssl_client_soc...
net/socket/ssl_client_socket_pool_unittest.cc:69: // Just like
TestLoadTimingInfo, except DNS times are expected to be NULL, for
On 2012/12/14 04:08:35, eroman wrote:
> I don't like calling times "NULL". I think it would be clearer maybe as
> lowercase null, since it is a different nullity concept.

Done (Modified other comments as well).

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
File net/socket/transport_client_socket_pool.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool.cc:210:
DCHECK(connect_timing().connect_start != base::TimeTicks());
On 2012/12/14 04:08:35, eroman wrote:
> might want to test is_null() throughout for consistency.

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
File net/socket/transport_client_socket_pool_unittest.cc (right):

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:38: // Make sure |handle|
sets load times are set correctly when it has been
On 2012/12/14 04:08:35, eroman wrote:
> weird

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:62: // Make sure |handle|
sets load times are set correctly when it has been
On 2012/12/14 04:08:35, eroman wrote:
> weird

Done.

https://codereview.chromium.org/11428150/diff/47038/net/socket/transport_clie...
net/socket/transport_client_socket_pool_unittest.cc:64: // the own of a
connection where |is_reused| is false may consider the
On 2012/12/14 04:08:35, eroman wrote:
> weird

Done.

[mmenke, 2013-01-02 16:16:43]

eroman:  Ping!

There's no rush.  Know you're sheriff today, but want to get this in your queue.

[eroman, 2013-01-02 21:26:46]

thanks for reminder! totally forgot about that.

Will publish new comments later today, apologies for that.


On Wed, Jan 2, 2013 at 8:16 AM, <mmenke@chromium.org> wrote:

> eroman:  Ping!
>
> There's no rush.  Know you're sheriff today, but want to get this in your
> queue.
>
>
https://codereview.chromium.**org/11428150/<https://codereview.chromium.org/1...
>

[mmenke, 2013-01-04 16:33:42]

Noticed you commented on year in another CL.

https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info.h
File net/base/load_timing_info.h (right):

https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info...
net/base/load_timing_info.h:1: // Copyright (c) 2012 The Chromium Authors. All
rights reserved.
I left these as 2013, since there are no clear guidelines...Initial upload time?
 When the file was first created?  First review time?  Commit time?

[mmenke, 2013-01-04 16:34:00]

Err...left them as 2012.

On 2013/01/04 16:33:42, Matt Menke wrote:
> Noticed you commented on year in another CL.
> 
>
https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info.h
> File net/base/load_timing_info.h (right):
> 
>
https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info...
> net/base/load_timing_info.h:1: // Copyright (c) 2012 The Chromium Authors. All
> rights reserved.
> I left these as 2013, since there are no clear guidelines...Initial upload
time?
>  When the file was first created?  First review time?  Commit time?

[eroman, 2013-01-05 00:30:15]

lgtm

https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info.h
File net/base/load_timing_info.h (right):

https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info...
net/base/load_timing_info.h:1: // Copyright (c) 2012 The Chromium Authors. All
rights reserved.
On 2013/01/04 16:33:42, Matt Menke wrote:
> I left these as 2013, since there are no clear guidelines...Initial upload
time?
>  When the file was first created?  First review time?  Commit time?

Sounds fine to me.

https://codereview.chromium.org/11428150/diff/65009/net/base/load_timing_info...
net/base/load_timing_info.h:35: // after the request_start and proxy events.
Thanks, I prefer the new wording!

https://codereview.chromium.org/11428150/diff/65009/net/socket/connect_timing.h
File net/socket/connect_timing.h (right):

https://codereview.chromium.org/11428150/diff/65009/net/socket/connect_timing...
net/socket/connect_timing.h:15: // These are all set by ConnectJobs.  See
base/load_timing.h for field
Do you think it is worth combining these guys using either composition or
inheritance? (i.e. LoadTimingInfo contains a ConnectTiming field).

[mmenke, 2013-01-05 03:53:13]

https://codereview.chromium.org/11428150/diff/65009/net/socket/connect_timing.h
File net/socket/connect_timing.h (right):

https://codereview.chromium.org/11428150/diff/65009/net/socket/connect_timing...
net/socket/connect_timing.h:15: // These are all set by ConnectJobs.  See
base/load_timing.h for field
On 2013/01/05 00:30:15, eroman wrote:
> Do you think it is worth combining these guys using either composition or
> inheritance? (i.e. LoadTimingInfo contains a ConnectTiming field).

I've gone back and forth on this:  The main reason it's a separate class is
because LoadTiming is an externally visible class, and ConnectTiming can live
only in net.

That having been said, if we moved ConnectTiming to LoadTiming.h, I'm perfectly
happy to unify them.  I don't think embedders should have to deal with fairly
complicated documentation split between two files.

Initially I was planning to avoid distinction between these times in
LoadTiming.h, but now that we're doing so, I think it's reasonable to make the
separate class externally visible.

Because of the distinction, I think composition is preferable.  I'll go ahead
and do that, making it a public inner class of LoadTiming.  If you think a
different approach is preferable, I'm happy to adjust.

[commit-bot: I haz the power, 2013-01-07 20:49:41]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/mmenke@chromium.org/11428150/99003