net: Return LoadTiming information in the case of a cache hit

net:  Return LoadTiming information in the case of a cache hit.
If the request went over the wire before headers were returned,
return information about the last over the wire request.  Otherwise,
set send times to be when the cache entry was opened, and
receive_header_start to be when the headers were read.

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

[mmenke, 2013-05-10 18:32:26]

May have gone a bit overboard on the tests, since just have to modify 4 lines
per test to add support, but I prefer to play it safe.

Two of the calls to CacheLoadTimingInformation() don't affect the tests, and
were added just out of paranoia - the ones in DoSuccessfulSendRequest() and
SetupEntryForRead() don't seem to be needed, but I'd rather play it safe.

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

https://codereview.chromium.org/14625012/diff/14001/net/url_request/url_reque...
net/url_request/url_request.cc:1039: base::Time request_start_time =
load_timing_info_.request_start_time;
I'm not a big fan of this, but other solutions seem worse a little worse:

1)  Have HttpCache::Transaction::GetLoadTimingInfo back up the values it
overwrites (Seems more regression prone than this, though this isn't great in
that respect, either).

2)  Keep the times in separate variables, and use them in
URLRequest::GetLoadTimingInfo (Can't just use them here, since I believe some
request types skip this notification).  Seems a little weird to pluck them from
a different location in GetLoadTimingInfo().

[mmenke, 2013-05-10 19:51:20]

Forgot to include this:

gavin:  Please focus on http_cache_*
eric:  Please focus on everything else.

[gavinp, 2013-05-10 20:23:03]

Looks good. I'm pleased to see we'll distinguish between send_start and
request_start.

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
File net/http/http_cache_transaction.h (right):

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:16: #include "net/base/request_priority.h"
#include "net/base/load_timing_info.h"

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:389: // be non-NULL.  Only called before
deleting the old transaction.
I think "old network transaction" would make things clearer for me, as there's
three sorts of transactions I can think about here.

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:390: void CacheLoadTimingInformation();
In that vein, using "Cache" here to mean "make a copy of and keep" instead of
"the http disk cache" is... Confusing.

I propose:

CopyLoadTimingInformationFromNetworkTransaction().

Or even:

ResetNetworkTransaction();

(and move network_trans_.reset() into the method).

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
File net/http/http_cache_unittest.cc (right):

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_unittest.cc:1988: // Get the same URL again, but this time
we expect it to result
Awesome!

[mmenke, 2013-05-10 20:44:00]

Thanks for the feedback!

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
File net/http/http_cache_transaction.h (right):

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:16: #include "net/base/request_priority.h"
On 2013/05/10 20:23:03, gavinp wrote:
> #include "net/base/load_timing_info.h"

Since we just have a scoped_ptr, forward declared it instead.

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:389: // be non-NULL.  Only called before
deleting the old transaction.
On 2013/05/10 20:23:03, gavinp wrote:
> I think "old network transaction" would make things clearer for me, as there's
> three sorts of transactions I can think about here.

Done.  I agree that "old" is clearer.

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_transaction.h:390: void CacheLoadTimingInformation();
On 2013/05/10 20:23:03, gavinp wrote:
> In that vein, using "Cache" here to mean "make a copy of and keep" instead of
> "the http disk cache" is... Confusing.
> 
> I propose:
> 
> CopyLoadTimingInformationFromNetworkTransaction().
> 
> Or even:
> 
> ResetNetworkTransaction();
> 
> (and move network_trans_.reset() into the method).

Switched to ResetNetworkTransaction, since we always call them together.  For
some reason, was thinking there was a cleanup function where updating the cached
copy wasn't needed.

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
File net/http/http_cache_unittest.cc (right):

https://chromiumcodereview.appspot.com/14625012/diff/29006/net/http/http_cach...
net/http/http_cache_unittest.cc:1988: // Get the same URL again, but this time
we expect it to result
On 2013/05/10 20:23:03, gavinp wrote:
> Awesome!

The fact that I capitalized Get, or the sheer number of tests I updated?

[mmenke, 2013-05-14 14:33:12]

eroman:  Ping!
gavin:  Ping!

Talked with Chris, and his suggestion was to merge this (Since this fixes an M28
regression), rather than to revert the CL that switched to the new
implementation (Which was a pretty big and complicated CL).  So best to get this
in sooner rather than later.

[gavinp, 2013-05-14 14:36:05]

lgtm!

[eroman, 2013-05-15 01:11:49]

lgtm

the load timing stuff is surprisingly subtle. glad you are looking through it
all carefully.

as an aside, do you have ideas on how we will do long term maintenance for this
feature? right now it benefits from you looking at lots of results, but i dont
know if the unittests alone will be enough to catch future regressions as people
refactor code.

https://codereview.chromium.org/14625012/diff/43003/chrome/browser/net/load_t...
File chrome/browser/net/load_timing_browsertest.cc (right):

https://codereview.chromium.org/14625012/diff/43003/chrome/browser/net/load_t...
chrome/browser/net/load_timing_browsertest.cc:504: load_timing_deltas.dns_start
= RelativeTime(-1000300);
what is the significance of changing these times?

https://codereview.chromium.org/14625012/diff/43003/net/http/http_cache_trans...
File net/http/http_cache_transaction.h (right):

https://codereview.chromium.org/14625012/diff/43003/net/http/http_cache_trans...
net/http/http_cache_transaction.h:390: // |old_network_trans_load_timing_|,
which must NULL.
"which must NULL" --> something is missing

[mmenke, 2013-05-15 01:52:38]

https://codereview.chromium.org/14625012/diff/43003/chrome/browser/net/load_t...
File chrome/browser/net/load_timing_browsertest.cc (right):

https://codereview.chromium.org/14625012/diff/43003/chrome/browser/net/load_t...
chrome/browser/net/load_timing_browsertest.cc:504: load_timing_deltas.dns_start
= RelativeTime(-1000300);
On 2013/05/15 01:11:50, eroman wrote:
> what is the significance of changing these times?

Paranoia.  It used to be that request_start was time 0, so these were guaranteed
to be less than request_start just by being negative.  That's no longer the
case, now that we no longer can base all times off of request_start.

The old value of 100 seconds should be completely safe, but I'm paranoid, and
using a debugger or a hosed system can do odd things to timings.

The other test used just 100 milliseconds, which wouldn't have made the test
flaky, because they just need to be less than proxy_end, but I wanted them less
than request_start as well.


Other than the stuff up above, the only change in this file that was needed was
the EXPECT_EQ -> EXPECT_LE.  I wasn't able to get a failure before I made that
change, but it could well have caused flake, since it was an incorrect assertion
with the new code.

https://codereview.chromium.org/14625012/diff/43003/net/http/http_cache_trans...
File net/http/http_cache_transaction.h (right):

https://codereview.chromium.org/14625012/diff/43003/net/http/http_cache_trans...
net/http/http_cache_transaction.h:390: // |old_network_trans_load_timing_|,
which must NULL.
On 2013/05/15 01:11:50, eroman wrote:
> "which must NULL" --> something is missing

Done.

[mmenke, 2013-05-15 02:05:33]

On 2013/05/15 01:11:49, eroman wrote:
> lgtm
> 
> the load timing stuff is surprisingly subtle. glad you are looking through it
> all carefully.
> 
> as an aside, do you have ideas on how we will do long term maintenance for
this
> feature? right now it benefits from you looking at lots of results, but i dont
> know if the unittests alone will be enough to catch future regressions as
people
> refactor code.

This issue wasn't even caught by me - it was caught be trying to make WebKit
load timing layout tests run with the test shell / DRT (After LoadTiming was
hooked up there for this express purpose).

I agree that this is a huge concern - when this code breaks, it's very difficult
to notice, both because it only affects values that are not easily visible, and
because as long as the values are in the right range, it's difficult to tell if
they're accurate or not.

We could beef up unit tests a little by including 100 millisecond delays in
them, and then checking that the resulting times are different, but that only
gives us marginal improvements in test coverage.  Another option to beef up
tests is to more heavily mock stuff out in tests - mock out the hostresolver,
use an in-process test server, basically do everything in-process, and make sure
times are all distinct.

I don't think there's much we can about browser tests - since there can be skew
in the times reported by the different processes, we can't really make the
BrowserTests much more strict.

I'm not sure that better tests are enough, but I do think they're definitely
worth considering, and would be well worth the effort.

[commit-bot: I haz the power, 2013-05-15 16:30:35]

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

[commit-bot: I haz the power, 2013-05-15 18:30:33]

Retried try job too often on win_rel for step(s) content_browsertests
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...

[commit-bot: I haz the power, 2013-05-15 18:34:12]

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

[commit-bot: I haz the power, 2013-05-15 21:33:27]

Change committed as 200356