Fix bug which caused DNS time not to be reported by LoadTimingObserver.

Fix bug which caused DNS time not to be reported by LoadTimingObserver.

The problem was the LogBoundConnectJobToRequest() sets
SOCKET_POOL_BOUND_TO_CONNECT_JOB after RemoveConnectJob() ends
SOCKET_POOL_CONNECT_JOB. Since there is no chance to return to the event loop,
it is safe (although fragile), to store the last connect job record and access
that on SOCKET_POOL_BOUND_TO_CONNECT_JOB.

Also, after fixing the DNS issue, it became apparent that what was being
measured as connect time actually included more than just the TCP connect. So I
fixed that as well.

BUG=50229
TEST=LoadTimingObserverTest.*

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=53945

[pfeldman, 2010-07-27 06:25:07]

Eric, do you think we can call RemoveConnectJob after calling
LogBoundConnectJobToRequest in both branches of OnConnectJobComplete? I see it
behaving differently with this regard in the method, while we'd like connect job
record to be consistently 'alive' when request is being bound. Or what do I
miss?

http://codereview.chromium.org/3028026/diff/1/2
File chrome/browser/net/load_timing_observer.cc (left):

http://codereview.chromium.org/3028026/diff/1/2#oldcode128
chrome/browser/net/load_timing_observer.cc:128: case
net::NetLog::TYPE_SOCKET_POOL:
Connect time intentionally included a bit more than just tcp connect. The reason
is that when we reuse existing socket, we can block for seconds. So I was using
connecion_reused flag to differentiate between tcp connect and blocking time in
devtools while considering the connect time value. I thought 1) web timing would
not care and 2) web timing would appreciate reporting blocking time in place of
connecting when blocking took place. Otherwise it could be number of seconds
off. Probably should have been reflected in the docs.

http://codereview.chromium.org/3028026/diff/1/2
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/3028026/diff/1/2#newcode132
chrome/browser/net/load_timing_observer.cc:132: if (last_connect_job_id_ ==
connect_job_id &&
This looks fragile. Can we call RemoveConnectJob after calling
LogBoundConnectJobToRequest instead? This would sound logical to the network log
clients and would not require the hack.

http://codereview.chromium.org/3028026/diff/1/2#newcode156
chrome/browser/net/load_timing_observer.cc:156: timing.connect_start =
TimeTicksToOffset(it->second.tcp_start, record);
80 chars please.

[tonyg, 2010-07-27 14:47:17]

On Mon, Jul 26, 2010 at 11:25 PM, <pfeldman@chromium.org> wrote:

> Eric, do you think we can call RemoveConnectJob after calling
> LogBoundConnectJobToRequest in both branches of OnConnectJobComplete? I see
> it
> behaving differently with this regard in the method, while we'd like
> connect job
> record to be consistently 'alive' when request is being bound. Or what do I
> miss?
>
>
> http://codereview.chromium.org/3028026/diff/1/2
> File chrome/browser/net/load_timing_observer.cc (left):
>
> http://codereview.chromium.org/3028026/diff/1/2#oldcode128
> chrome/browser/net/load_timing_observer.cc:128: case
> net::NetLog::TYPE_SOCKET_POOL:
> Connect time intentionally included a bit more than just tcp connect.
> The reason is that when we reuse existing socket, we can block for
> seconds. So I was using connecion_reused flag to differentiate between
> tcp connect and blocking time in devtools while considering the connect
> time value. I thought 1) web timing would not care and 2) web timing
> would appreciate reporting blocking time in place of connecting when
> blocking took place. Otherwise it could be number of seconds off.
> Probably should have been reflected in the docs.
>

I'm okay with accepting the definition of connect time whether it includes
blocking time or not. As long as we define it, that really isn't an issue
because we have the requestTime base time which would either show elapsed
blocking time before connectStart or not.

The problem with using TYPE_SOCKET_POOL is that it includes DNS time. My
understanding was that all of these phases would be mutually exclusive. It
would be surprising and misleading to report that the connection began to be
established at the same time the DNS request was issued.

Cropping it down to TCP_CONNECT was one way I found to resolve this overlap
problem. Do you have a suggestion for a different phase that would include
connection blocking time but exclude DNS time?


>
> http://codereview.chromium.org/3028026/diff/1/2
> File chrome/browser/net/load_timing_observer.cc (right):
>
> http://codereview.chromium.org/3028026/diff/1/2#newcode132
> chrome/browser/net/load_timing_observer.cc:132: if (last_connect_job_id_
> == connect_job_id &&
> This looks fragile. Can we call RemoveConnectJob after calling
> LogBoundConnectJobToRequest instead? This would sound logical to the
> network log clients and would not require the hack.
>

Yes. It is fragile :-(

Eric and I discussed this at some length yesterday. He suggested the
approach in this patch as it is similar to what PassiveLogObserver does.
However, if you convince him, I'm happy to rewrite this patch to rearrange
the underlying calls or take any other workable approach.

The key thing we noticed after talking is that, in general,
LoadTimingObserver is fragile against refactors to the net stack. Part of
the problem is that there isn't a really good way to test it with the real
net stack code. While we couldn't think of anything better, the existing
test simulates the calls in the network stack so the tests don't break if
the actual calls are changed.

He suggested this as a short term fix, but the long term fix is to either
use separate, explicit timers or to at least figure out a way to write tests
such that they will fail if the underlying code is refactored.


>
> http://codereview.chromium.org/3028026/diff/1/2#newcode156
> chrome/browser/net/load_timing_observer.cc:156: timing.connect_start =
> TimeTicksToOffset(it->second.tcp_start, record);
> 80 chars please.
>
>
Oops. Will fix.


>
> http://codereview.chromium.org/3028026/show
>

[pfeldman, 2010-07-27 14:54:41]

> Cropping it down to TCP_CONNECT was one way I found to resolve this overlap
> problem. Do you have a suggestion for a different phase that would include
> connection blocking time but exclude DNS time?

Either introduce explicit "blocking" timer or subtract it from connect time?

> Yes. It is fragile :-(
> 
> Eric and I discussed this at some length yesterday. He suggested the
> approach in this patch as it is similar to what PassiveLogObserver does.
> However, if you convince him, I'm happy to rewrite this patch to rearrange
> the underlying calls or take any other workable approach.

I am fine with it as a short term fix. Knowing how to test the load time
observer
would be great. Can we replay network activity in the network stack using
listen socket or something similar in combination with mock timers?

[tonyg, 2010-07-27 15:55:28]

On Tue, Jul 27, 2010 at 7:54 AM, <pfeldman@chromium.org> wrote:

>  Cropping it down to TCP_CONNECT was one way I found to resolve this
>> overlap
>> problem. Do you have a suggestion for a different phase that would include
>> connection blocking time but exclude DNS time?
>>
>
> Either introduce explicit "blocking" timer or subtract it from connect
> time?


I see now that resource_loader_bridge.h documents connect_start/end as
including DNS time. I apologize I didn't notice that before.

I'd still like to appeal the following:
1. The phases in LoadTimingInfo should be mutually exclusive
2. Typically developers don't think of establishing the connection as
including DNS time
3. If the definition were narrowed to only include the time to establish the
TCP connection, blocking time is still implicitly available from
{base_time|dns_end|proxy_end} to connect_start.

If you still think that the connect phase should include DNS time, then I'll
document that in the WebCore ResourceLoadTiming API so that other platforms
will know to do the same and modify the WebCore Web Timing code to take
connectStart to be the later of {dns_end|connect_start}.


>
>  Yes. It is fragile :-(
>>
>
>  Eric and I discussed this at some length yesterday. He suggested the
>> approach in this patch as it is similar to what PassiveLogObserver does.
>> However, if you convince him, I'm happy to rewrite this patch to rearrange
>> the underlying calls or take any other workable approach.
>>
>
> I am fine with it as a short term fix. Knowing how to test the load time
> observer
> would be great. Can we replay network activity in the network stack using
> listen socket or something similar in combination with mock timers?
>
>
> http://codereview.chromium.org/3028026/show
>

[pfeldman, 2010-07-27 17:15:17]

>> If the definition were narrowed to only include the time to establish the TCP
connection, blocking time is still implicitly available from
{base_time|dns_end|proxy_end} to connect_start.

I am not sure I understand - there is no TCP connection to get connect_start in
case of blocked connection.

[tonyg, 2010-07-27 18:26:22]

On 2010/07/27 17:15:17, pfeldman wrote:
> >> If the definition were narrowed to only include the time to establish the
TCP
> connection, blocking time is still implicitly available from
> {base_time|dns_end|proxy_end} to connect_start.
> 
> I am not sure I understand - there is no TCP connection to get connect_start
in
> case of blocked connection.

Per our offline conversation, I've reverted my change to the definition of the
connect phase and updated the description of the connect phase in
resource_loader_bridge.h.

PTAL.

[pfeldman, 2010-07-27 18:30:33]

LGTM with a nit. Thanks for fixing this.

http://codereview.chromium.org/3028026/diff/9001/10001
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/3028026/diff/9001/10001#newcode51
chrome/browser/net/load_timing_observer.cc:51:
LoadTimingObserver::LoadTimingObserver() : last_connect_job_id_(-1) {
net::NetLog::Source::kInvalidId

[tonyg, 2010-07-27 20:33:52]

On 2010/07/27 18:30:33, pfeldman wrote:
> LGTM with a nit. Thanks for fixing this.
> 
> http://codereview.chromium.org/3028026/diff/9001/10001
> File chrome/browser/net/load_timing_observer.cc (right):
> 
> http://codereview.chromium.org/3028026/diff/9001/10001#newcode51
> chrome/browser/net/load_timing_observer.cc:51:
> LoadTimingObserver::LoadTimingObserver() : last_connect_job_id_(-1) {
> net::NetLog::Source::kInvalidId

Thanks. Fixed.

Eric, do you want to take a quick pass too?

[eroman, 2010-07-27 23:54:06]

lgtm

http://codereview.chromium.org/3028026/diff/15001/16001
File chrome/browser/net/load_timing_observer.cc (right):

http://codereview.chromium.org/3028026/diff/15001/16001#newcode206
chrome/browser/net/load_timing_observer.cc:206:
connect_job_to_record_.find(source.id);
nit: indent by 4.

[tonyg, 2010-07-27 23:58:46]

On 2010/07/27 23:54:06, eroman wrote:
> lgtm
> 
> http://codereview.chromium.org/3028026/diff/15001/16001
> File chrome/browser/net/load_timing_observer.cc (right):
> 
> http://codereview.chromium.org/3028026/diff/15001/16001#newcode206
> chrome/browser/net/load_timing_observer.cc:206:
> connect_job_to_record_.find(source.id);
> nit: indent by 4.
Thanks. Fixed.