Fix a load timing bug in the case of SPDY session reuse

Fix a load timing bug in which proxy resolution times could
be before request start in the case of reusing a SPDY session
(Or HTTP pipeline, though HTTP pipelining is disabled by
default).

Also move logic to fix up LoadTimingInfo into net/, to reduce
chrome's dependency on internal net/ details.

BUG=225935
R=eroman@chromium.org
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=192863

[mmenke, 2013-04-04 18:43:09]

Hmm...Sending a lot of CLs your way this week.

[mmenke, 2013-04-04 20:21:11]

On 2013/04/04 18:43:09, mmenke wrote:
> Hmm...Sending a lot of CLs your way this week.

On second thought, this is net specific enough that it should probably be moved
into url_request, as much as I prefer url_request not to have to know about
Javascript APIs.

Hold off on reviewing this while I move this into URLRequest and add some tests.

[mmenke, 2013-04-05 15:02:57]

On 2013/04/04 20:21:11, mmenke wrote:
> On 2013/04/04 18:43:09, mmenke wrote:
> > Hmm...Sending a lot of CLs your way this week.
> 
> On second thought, this is net specific enough that it should probably be
moved
> into url_request, as much as I prefer url_request not to have to know about
> Javascript APIs.
> 
> Hold off on reviewing this while I move this into URLRequest and add some
tests.

[eroman]  This is now ready for review.

[eroman, 2013-04-06 01:02:02]

lgtm

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/base/load_timi...
File net/base/load_timing_info.h (right):

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/base/load_timi...
net/base/load_timing_info.h:40: // Times represent the length of time that the
request was blocked on an event,
This comment confused me on the first read (I thought it was implying the times
were durations rather than points in time).

Perhaps what threw me was "length of time"

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
File net/url_request/url_request.cc (right):

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
net/url_request/url_request.cc:90: void FixupLoadTimingInfo(net::LoadTimingInfo*
load_timing_info) {
The description is pretty clear on what this does, but the function name could
be improved.

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
net/url_request/url_request.cc:1039: FixupLoadTimingInfo(&load_timing_info_);
This seems fragile (different meanings at different levels). I can't think of a
problem at the moment, but seems like a subtle problem waiting to happen again.

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
File net/url_request/url_request_test_job.h (right):

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
net/url_request/url_request_test_job.h:94: void set_load_timing_info(const
LoadTimingInfo& load_timing_info) {
Is this needed (since the member is protected)

[mmenke, 2013-04-06 01:35:24]

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
File net/url_request/url_request.cc (right):

https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
net/url_request/url_request.cc:1039: FixupLoadTimingInfo(&load_timing_info_);
On 2013/04/06 01:02:02, eroman wrote:
> This seems fragile (different meanings at different levels). I can't think of
a
> problem at the moment, but seems like a subtle problem waiting to happen
again.

I agree...  Since we dig down all the way to the socket to get this information,
we could have the lower levels of the network stack do this logic - the
HttpTransaction can "fix" the proxy times if needed, and the socket itself can
"fix" the connect times.

The downside to this is I'm not sure it can reasonably be unit tested.  It also
somewhat masks the issue - the whole incremental retrieval at each level process
is a little weird.

Worth the switch?

[mmenke, 2013-04-06 17:12:36]

On 2013/04/06 01:35:24, mmenke wrote:
>
https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
> File net/url_request/url_request.cc (right):
> 
>
https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
> net/url_request/url_request.cc:1039: FixupLoadTimingInfo(&load_timing_info_);
> On 2013/04/06 01:02:02, eroman wrote:
> > This seems fragile (different meanings at different levels). I can't think
of
> a
> > problem at the moment, but seems like a subtle problem waiting to happen
> again.
> 
> I agree...  Since we dig down all the way to the socket to get this
information,
> we could have the lower levels of the network stack do this logic - the
> HttpTransaction can "fix" the proxy times if needed, and the socket itself can
> "fix" the connect times.
> 
> The downside to this is I'm not sure it can reasonably be unit tested.  It
also
> somewhat masks the issue - the whole incremental retrieval at each level
process
> is a little weird.
> 
> Worth the switch?

Think I'll plan to land this as-is, and then think about the other approach - it
can actually be unit tested, but may not have time to work tests for a week or
so, and want to get rid of the DCHECKs in the interim.

[mmenke, 2013-04-06 17:16:44]

On 2013/04/06 17:12:36, mmenke wrote:
> On 2013/04/06 01:35:24, mmenke wrote:
> >
>
https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
> > File net/url_request/url_request.cc (right):
> > 
> >
>
https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/ur...
> > net/url_request/url_request.cc:1039:
FixupLoadTimingInfo(&load_timing_info_);
> > On 2013/04/06 01:02:02, eroman wrote:
> > > This seems fragile (different meanings at different levels). I can't think
> of
> > a
> > > problem at the moment, but seems like a subtle problem waiting to happen
> > again.
> > 
> > I agree...  Since we dig down all the way to the socket to get this
> information,
> > we could have the lower levels of the network stack do this logic - the
> > HttpTransaction can "fix" the proxy times if needed, and the socket itself
can
> > "fix" the connect times.
> > 
> > The downside to this is I'm not sure it can reasonably be unit tested.  It
> also
> > somewhat masks the issue - the whole incremental retrieval at each level
> process
> > is a little weird.
> > 
> > Worth the switch?
> 
> Think I'll plan to land this as-is, and then think about the other approach -
it
> can actually be unit tested, but may not have time to work tests for a week or
> so, and want to get rid of the DCHECKs in the interim.

(As-is modulo response to your comments, that is)

[eroman, 2013-04-07 01:10:50]

Definitely good to check-in as is. Still LGTM


On Sat, Apr 6, 2013 at 10:16 AM, <mmenke@chromium.org> wrote:

> On 2013/04/06 17:12:36, mmenke wrote:
>
>> On 2013/04/06 01:35:24, mmenke wrote:
>> >
>>
>
> https://chromiumcodereview.**appspot.com/13653003/diff/**
>
29005/net/url_request/url_**request.cc<https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/url_request.cc>
>
>> > File net/url_request/url_request.cc (right):
>> >
>> >
>>
>
> https://chromiumcodereview.**appspot.com/13653003/diff/**
>
29005/net/url_request/url_**request.cc#newcode1039<https://chromiumcodereview.appspot.com/13653003/diff/29005/net/url_request/url_request.cc#newcode1039>
>
>> > net/url_request/url_request.**cc:1039:
>>
> FixupLoadTimingInfo(&load_**timing_info_);
>
>> > On 2013/04/06 01:02:02, eroman wrote:
>> > > This seems fragile (different meanings at different levels). I can't
>> think
>> of
>> > a
>> > > problem at the moment, but seems like a subtle problem waiting to
>> happen
>> > again.
>> >
>> > I agree...  Since we dig down all the way to the socket to get this
>> information,
>> > we could have the lower levels of the network stack do this logic - the
>> > HttpTransaction can "fix" the proxy times if needed, and the socket
>> itself
>>
> can
>
>> > "fix" the connect times.
>> >
>> > The downside to this is I'm not sure it can reasonably be unit tested.
>>  It
>> also
>> > somewhat masks the issue - the whole incremental retrieval at each level
>> process
>> > is a little weird.
>> >
>> > Worth the switch?
>>
>
>  Think I'll plan to land this as-is, and then think about the other
>> approach -
>>
> it
>
>> can actually be unit tested, but may not have time to work tests for a
>> week or
>> so, and want to get rid of the DCHECKs in the interim.
>>
>
> (As-is modulo response to your comments, that is)
>
>
https://codereview.chromium.**org/13653003/<https://codereview.chromium.org/1...
>

[mmenke, 2013-04-08 15:31:24]

sky:  Please review
chrome/browser/renderer_host/chrome_resource_dispatcher_host_delegate.cc - I'm
basically moving some logic into net/ that probably should have been there in
the first place, in addition to fixing a bug.

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

https://codereview.chromium.org/13653003/diff/29005/net/base/load_timing_info...
net/base/load_timing_info.h:40: // Times represent the length of time that the
request was blocked on an event,
On 2013/04/06 01:02:02, eroman wrote:
> This comment confused me on the first read (I thought it was implying the
times
> were durations rather than points in time).
> 
> Perhaps what threw me was "length of time"

Updated it to say "times represent when a request starts/stops block on an
events"

https://codereview.chromium.org/13653003/diff/29005/net/url_request/url_reque...
File net/url_request/url_request.cc (right):

https://codereview.chromium.org/13653003/diff/29005/net/url_request/url_reque...
net/url_request/url_request.cc:90: void FixupLoadTimingInfo(net::LoadTimingInfo*
load_timing_info) {
On 2013/04/06 01:02:02, eroman wrote:
> The description is pretty clear on what this does, but the function name could
> be improved.

Renamed to "ConvertRealLoadTimesToBlockingTimes".  A bit of a mouthful, but it's
accurate, and not called a lot.  :)

https://codereview.chromium.org/13653003/diff/29005/net/url_request/url_reque...
File net/url_request/url_request_test_job.h (right):

https://codereview.chromium.org/13653003/diff/29005/net/url_request/url_reque...
net/url_request/url_request_test_job.h:94: void set_load_timing_info(const
LoadTimingInfo& load_timing_info) {
On 2013/04/06 01:02:02, eroman wrote:
> Is this needed (since the member is protected)

It is if we don't want to create another subclass - the test creates
URLRequestTestJobs directly, rather than a subclass.

We could remove all the added load timing stuff here, and add it to a subclass,
but I don't think that gets us much.  Other tests may find it useful in the
future, and it doesn't break any old behavior or add significant complexity.

[sky, 2013-04-08 15:42:34]

LGTM

[mmenke, 2013-04-08 15:43:25]

On 2013/04/08 15:42:34, sky wrote:
> LGTM

Thanks!

[commit-bot: I haz the power, 2013-04-08 15:43:41]

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

[commit-bot: I haz the power, 2013-04-08 15:53:30]

Sorry for I got bad news for ya.
Compile failed with a clobber build on linux_chromeos_clang.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=linux_chro...
Your code is likely broken or HEAD is junk. Please ensure your
code is not broken then alert the build sheriffs.
Look at the try server FAQ for more details.

[commit-bot: I haz the power, 2013-04-08 18:19:35]

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

[mmenke, 2013-04-08 19:51:02]

Committed patchset #6 manually as r192863 (presubmit successful).