[Resource Timing] Expose redirect timing information

[Resource Timing] Expose redirect timing information

This change contains redirect timing information for W3C Resource Timing spec, and tests.

Contributed by pan.deng@intel.com

BUG=None

Committed: https://src.chromium.org/viewvc/blink?view=rev&revision=152077

[Pan, 2013-04-17 15:38:15]

Some issues I observed, maybe not bugs, but I don't understand:
1, loadTiming is not always there in ResourceResponse.
2, iframes with resource redirect won't be reported in CachedResourceLoader.

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
Source/core/page/Performance.cpp:207: ASSERT(loadTiming);
I observed that resourceLoadTiming is not contained in redirect reponse with
latest chromium code, I guess reason is browser process network stack doesn't
make it, will it be always exist there in future?

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
Source/core/page/PerformanceResourceTiming.cpp:92: ASSERT(m_timing.get());
in domainLoopUpStart/end connectStart/end, if m_timing is not existed, it will
fall back to fetchStart(), then what about fetchStart()? if loadTiming missing
in final response is common, shall we record the initialTime of any inner
request in ResourceLoader::willSendRequest?

[James Simonsen, 2013-04-18 02:57:37]

Sorry, I didn't get a chance to review this today, but I wanted to at least
answer your questions in the meantime.

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
Source/core/page/Performance.cpp:207: ASSERT(loadTiming);
On 2013/04/17 15:38:16, Pan wrote:
> I observed that resourceLoadTiming is not contained in redirect reponse with
> latest chromium code, I guess reason is browser process network stack doesn't
> make it, will it be always exist there in future?

That's determined entirely by Blink, not Chrome.
ResourceLoadNotifier::dispatchWillSendRequest() is where we
setReportLoadTiming(true). The redirect must go through a path where that isn't
called. You should find it and fix it (in this CL).

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
Source/core/page/PerformanceResourceTiming.cpp:92: ASSERT(m_timing.get());
On 2013/04/17 15:38:16, Pan wrote:
> in domainLoopUpStart/end connectStart/end, if m_timing is not existed, it will
> fall back to fetchStart(), then what about fetchStart()? if loadTiming missing
> in final response is common, shall we record the initialTime of any inner
> request in ResourceLoader::willSendRequest? 

I think we should go back to initiationTime, though I expect that once the other
bug is fixed, that should never happen. Perhaps it's best to just
ASSERT(m_timing) in the constructor.

[Pan, 2013-04-18 03:08:59]

On 2013/04/18 02:57:37, James Simonsen wrote:
> Sorry, I didn't get a chance to review this today, but I wanted to at least
> answer your questions in the meantime.
> 
>
https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
> File Source/core/page/Performance.cpp (right):
> 
>
https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
> Source/core/page/Performance.cpp:207: ASSERT(loadTiming);
> On 2013/04/17 15:38:16, Pan wrote:
> > I observed that resourceLoadTiming is not contained in redirect reponse with
> > latest chromium code, I guess reason is browser process network stack
doesn't
> > make it, will it be always exist there in future?
> 
> That's determined entirely by Blink, not Chrome.
> ResourceLoadNotifier::dispatchWillSendRequest() is where we
> setReportLoadTiming(true). The redirect must go through a path where that
isn't
> called. You should find it and fix it (in this CL).
> 
As my previous quick investigation, the redirect request setReportLoadTiming()
is set there, anyway, I'll validate and fix the problem.

thanks!
Pan

[Pan, 2013-04-18 14:00:32]

On 2013/04/18 03:08:59, Pan wrote:
> On 2013/04/18 02:57:37, James Simonsen wrote:
> > Sorry, I didn't get a chance to review this today, but I wanted to at least
> > answer your questions in the meantime.
> > 
> >
>
https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
> > File Source/core/page/Performance.cpp (right):
> > 
> >
>
https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
> > Source/core/page/Performance.cpp:207: ASSERT(loadTiming);
> > On 2013/04/17 15:38:16, Pan wrote:
> > > I observed that resourceLoadTiming is not contained in redirect reponse
with
> > > latest chromium code, I guess reason is browser process network stack
> doesn't
> > > make it, will it be always exist there in future?
> > 
> > That's determined entirely by Blink, not Chrome.
> > ResourceLoadNotifier::dispatchWillSendRequest() is where we
> > setReportLoadTiming(true). The redirect must go through a path where that
> isn't
> > called. You should find it and fix it (in this CL).
> > 
> As my previous quick investigation, the redirect request setReportLoadTiming()
> is set there, anyway, I'll validate and fix the problem.

Latest finding: for D request R1 redirect to R2.
1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser process
correctly. (although there is useless condition and set in ResourceLoadNotifier,
I guess left there because of remove macro RESOURCE_TIMING)
2) In chromium network stack, when request R1, HttpCache::Transaction and
HttpNetworkTransaction are created, and timeticks will be recorded in
statemachine of later. while when back from render process and request R2, seems
response of R2 is already there(!!! how?) and no HttpNetworkTransaction will be
created, no real request will be sent anymore, so that loadTiming of R2 is not
complete, and then in webkit/glue/weburlloader_impl.cc, info.load_timing of R2
is not populated.

I think it should be a problem of chromium network stack, if loadTiming is not
always there or incomplete, it's hard to deliver the real timestamps.

[James Simonsen, 2013-04-18 16:52:09]

[+mmenke]

On 2013/04/18 14:00:32, Pan wrote:
> Latest finding: for D request R1 redirect to R2.
> 1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser process
> correctly. (although there is useless condition and set in
ResourceLoadNotifier,
> I guess left there because of remove macro RESOURCE_TIMING)
> 2) In chromium network stack, when request R1, HttpCache::Transaction and
> HttpNetworkTransaction are created, and timeticks will be recorded in
> statemachine of later. while when back from render process and request R2,
seems
> response of R2 is already there(!!! how?) and no HttpNetworkTransaction will
be
> created, no real request will be sent anymore, so that loadTiming of R2 is not
> complete, and then in webkit/glue/weburlloader_impl.cc, info.load_timing of R2
> is not populated.
> 
> I think it should be a problem of chromium network stack, if loadTiming is not
> always there or incomplete, it's hard to deliver the real timestamps.

Matt, you were in here recently. Any thoughts? If not, I'll try to look later
today.

[mmenke, 2013-04-18 17:03:53]

On 2013/04/18 16:52:09, James Simonsen wrote:
> [+mmenke]
> 
> On 2013/04/18 14:00:32, Pan wrote:
> > Latest finding: for D request R1 redirect to R2.
> > 1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser process
> > correctly. (although there is useless condition and set in
> ResourceLoadNotifier,
> > I guess left there because of remove macro RESOURCE_TIMING)
> > 2) In chromium network stack, when request R1, HttpCache::Transaction and
> > HttpNetworkTransaction are created, and timeticks will be recorded in
> > statemachine of later. while when back from render process and request R2,
> seems
> > response of R2 is already there(!!! how?) and no HttpNetworkTransaction will
> be
> > created, no real request will be sent anymore, so that loadTiming of R2 is
not
> > complete, and then in webkit/glue/weburlloader_impl.cc, info.load_timing of
R2
> > is not populated.
> > 
> > I think it should be a problem of chromium network stack, if loadTiming is
not
> > always there or incomplete, it's hard to deliver the real timestamps.
> 
> Matt, you were in here recently. Any thoughts? If not, I'll try to look later
> today.

I'm having trouble understanding the description of the problem.

[mmenke, 2013-04-18 17:07:24]

On 2013/04/18 17:03:53, mmenke wrote:
> On 2013/04/18 16:52:09, James Simonsen wrote:
> > [+mmenke]
> > 
> > On 2013/04/18 14:00:32, Pan wrote:
> > > Latest finding: for D request R1 redirect to R2.
> > > 1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser
process
> > > correctly. (although there is useless condition and set in
> > ResourceLoadNotifier,
> > > I guess left there because of remove macro RESOURCE_TIMING)
> > > 2) In chromium network stack, when request R1, HttpCache::Transaction and
> > > HttpNetworkTransaction are created, and timeticks will be recorded in
> > > statemachine of later. while when back from render process and request R2,
> > seems
> > > response of R2 is already there(!!! how?) and no HttpNetworkTransaction
will
> > be
> > > created, no real request will be sent anymore, so that loadTiming of R2 is
> not
> > > complete, and then in webkit/glue/weburlloader_impl.cc, info.load_timing
of
> R2
> > > is not populated.
> > > 
> > > I think it should be a problem of chromium network stack, if loadTiming is
> not
> > > always there or incomplete, it's hard to deliver the real timestamps.
> > 
> > Matt, you were in here recently. Any thoughts? If not, I'll try to look
later
> > today.
> 
> I'm having trouble understanding the description of the problem.

Requests that reuse sockets don't have connection times (Including the real
connection times breaks quite a number of things).  We also don't include any
times except request_start for entries fetched from the cache.

[mmenke, 2013-04-18 17:10:03]

On 2013/04/18 17:07:24, mmenke wrote:
> On 2013/04/18 17:03:53, mmenke wrote:
> > On 2013/04/18 16:52:09, James Simonsen wrote:
> > > [+mmenke]
> > > 
> > > On 2013/04/18 14:00:32, Pan wrote:
> > > > Latest finding: for D request R1 redirect to R2.
> > > > 1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser
> process
> > > > correctly. (although there is useless condition and set in
> > > ResourceLoadNotifier,
> > > > I guess left there because of remove macro RESOURCE_TIMING)
> > > > 2) In chromium network stack, when request R1, HttpCache::Transaction
and
> > > > HttpNetworkTransaction are created, and timeticks will be recorded in
> > > > statemachine of later. while when back from render process and request
R2,
> > > seems
> > > > response of R2 is already there(!!! how?) and no HttpNetworkTransaction
> will
> > > be
> > > > created, no real request will be sent anymore, so that loadTiming of R2
is
> > not
> > > > complete, and then in webkit/glue/weburlloader_impl.cc, info.load_timing
> of
> > R2
> > > > is not populated.
> > > > 
> > > > I think it should be a problem of chromium network stack, if loadTiming
is
> > not
> > > > always there or incomplete, it's hard to deliver the real timestamps.
> > > 
> > > Matt, you were in here recently. Any thoughts? If not, I'll try to look
> later
> > > today.
> > 
> > I'm having trouble understanding the description of the problem.
> 
> Requests that reuse sockets don't have connection times (Including the real
> connection times breaks quite a number of things).  We also don't include any
> times except request_start for entries fetched from the cache.

Oh...right...Blink gets very sad and cries when there's no received response
headers time.  Other times, it defaults to the preceding time when they're left
blank.  As a result, I made glue not pass along times when there are no response
headers times.  I was thinking this would just affect non-HTTP requests, but it
would affect requests with cached responses, too.

[Pan, 2013-04-19 01:48:33]

On 2013/04/18 17:10:03, mmenke wrote:
> On 2013/04/18 17:07:24, mmenke wrote:
> > On 2013/04/18 17:03:53, mmenke wrote:
> > > On 2013/04/18 16:52:09, James Simonsen wrote:
> > > > [+mmenke]
> > > > 
> > > > On 2013/04/18 14:00:32, Pan wrote:
> > > > > Latest finding: for D request R1 redirect to R2.
> > > > > 1) Requests of R1 and R2 are set reportLoadTiming and IPC to browser
> > process
> > > > > correctly. (although there is useless condition and set in
> > > > ResourceLoadNotifier,
> > > > > I guess left there because of remove macro RESOURCE_TIMING)
> > > > > 2) In chromium network stack, when request R1, HttpCache::Transaction
> and
> > > > > HttpNetworkTransaction are created, and timeticks will be recorded in
> > > > > statemachine of later. while when back from render process and request
> R2,
> > > > seems
> > > > > response of R2 is already there(!!! how?) and no
HttpNetworkTransaction
> > will
> > > > be
> > > > > created, no real request will be sent anymore, so that loadTiming of
R2
> is
> > > not
> > > > > complete, and then in webkit/glue/weburlloader_impl.cc,
info.load_timing
> > of
> > > R2
> > > > > is not populated.
> > > > > 
> > > > > I think it should be a problem of chromium network stack, if
loadTiming
> is
> > > not
> > > > > always there or incomplete, it's hard to deliver the real timestamps.
> > > > 
> > > > Matt, you were in here recently. Any thoughts? If not, I'll try to look
> > later
> > > > today.
> > > 
> > > I'm having trouble understanding the description of the problem.
> > 
> > Requests that reuse sockets don't have connection times (Including the real
> > connection times breaks quite a number of things).  We also don't include
any
> > times except request_start for entries fetched from the cache.
> 
> Oh...right...Blink gets very sad and cries when there's no received response
> headers time.  Other times, it defaults to the preceding time when they're
left
> blank.  As a result, I made glue not pass along times when there are no
response
> headers times.  I was thinking this would just affect non-HTTP requests, but
it
> would affect requests with cached responses, too.

thank you Matt! some other chromium net questions need your help :)
1, why entry B is in cache? because it just has been fetched by last request of
A? or once receive this request of A, found it is a redirect, then pre-request B
even before blink part come back?
2, why A is always not in cache?

Regards
Pan

[Pan, 2013-04-19 14:54:59]

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
Source/core/page/Performance.cpp:208: lastRedirectEndTime =
loadTiming->convertResourceLoadTimeToMonotonicTime(loadTiming->receiveHeadersEnd);
can we assume redirect response will never be cached in network stack? in other
word, only final response can be cached in network stack, so that we can get
lastRedirectEndTime in network stack, otherwise we have to catch that value in
blink(ResourceLoader::willSendRequest).

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
Source/core/page/PerformanceResourceTiming.cpp:94: return
monotonicTimeToDocumentMilliseconds(m_requestingDocument.get(),
m_timing->requestTime);
For redirect case, we need m_timing->requestTime here. Currently as "no received
response headers time" is filtered in glue, we won't get m_timing and its
requestTime here.
1) Can we let m_timing of http cached response(just requestTime there) pass
through glue? I really expect this, if true, consider 2), if not got to 3)
2) can we assume that timing of cached(network stack) response only has
requestTime, that of network response also have other break down timestamps? I
expected this, however I observed there are blank requestTime when run layout
test case by DRT.(never happened in real chromium test).
3) we have to catch any request initial Time in ResourceLoader::willSendRequest,
and let the last one as fetchStart in redirect case.

[James Simonsen, 2013-04-23 00:31:37]

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance.cpp
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/Performance....
Source/core/page/Performance.cpp:208: lastRedirectEndTime =
loadTiming->convertResourceLoadTimeToMonotonicTime(loadTiming->receiveHeadersEnd);
On 2013/04/19 14:54:59, Pan wrote:
> can we assume redirect response will never be cached in network stack?

No, we do cache redirects. There's a bug to do a better job of it here:

https://code.google.com/p/chromium/issues/detail?id=49573

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/1/Source/core/page/PerformanceR...
Source/core/page/PerformanceResourceTiming.cpp:94: return
monotonicTimeToDocumentMilliseconds(m_requestingDocument.get(),
m_timing->requestTime);
On 2013/04/19 14:54:59, Pan wrote:
> For redirect case, we need m_timing->requestTime here. Currently as "no
received
> response headers time" is filtered in glue, we won't get m_timing and its
> requestTime here.
> 1) Can we let m_timing of http cached response(just requestTime there) pass
> through glue?

Yeah, that seems like the right thing to do.

> 2) can we assume that timing of cached(network stack) response only has
> requestTime, that of network response also have other break down timestamps? I
> expected this, however I observed there are blank requestTime when run layout
> test case by DRT.(never happened in real chromium test).

I believe Navigation Timing has explicit rules about which timing members should
be populated on a cache hit. So, these fields will be populated. If they're not,
it's a bug. And if Resource Timing doesn't use the same definitions as
Navigation Timing, it's a bug in the spec.

> 3) we have to catch any request initial Time in
ResourceLoader::willSendRequest,
> and let the last one as fetchStart in redirect case.

I like this idea. That's how Navigation Timing works.

We should store it in the initiator map. Perhaps we should rename that.

[Pan, 2013-04-23 15:20:18]

> > 1) Can we let m_timing of http cached response(just requestTime there) pass
> > through glue?
> 
> Yeah, that seems like the right thing to do.
>
@Matt, any idea about this? or I can help to find a solution tomorrow. 

> I believe Navigation Timing has explicit rules about which timing members
should
> be populated on a cache hit. So, these fields will be populated. If they're
not,
> it's a bug. And if Resource Timing doesn't use the same definitions as
> Navigation Timing, it's a bug in the spec.
> 
It is a test shell bug rather than spec bug.
I submit patch in https://codereview.chromium.org/14108004/, once this fixed,
DRT will always provide loadTiming info to blink, even the for cached request,
blink will get a "requestTime".
another related patch is https://codereview.chromium.org/13872022/, to pass
loadFinishTime to blink when run DRT.

> > 3) we have to catch any request initial Time in
> ResourceLoader::willSendRequest,
> > and let the last one as fetchStart in redirect case.
> 
> I like this idea. That's how Navigation Timing works.
> 
> We should store it in the initiator map. Perhaps we should rename that.
if m_timing will be always passed to blink, I think we can use the requestTime.
I just tried to catch fetchStart in ResourceLoader::willSendRequest today, a
risk is, final fetchStart time is fairly near last
redirectEnd(receive_headers_end in webkit/glue/weburlloader_impl.cc), during the
convert by TimeTicksToOffset() to match blink data structure, redirectEnd
timeDelta may be enlarged by InMillisecondsRoundedUp() and span final fetchStart
sometimes.


thanks
Pan

[Pan, 2013-04-23 15:27:38]

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.cpp:489: // <iframe>s should
report the initial navigation requested by the parent document, but not
subsequent navigations.
I don't quite understand here, and seems it affects 
some tests that use iframe, like
http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_resource_request.html
any idea? or I'm going to investigate tomorrow.

[Pan, 2013-04-25 12:40:51]

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.cpp:489: // <iframe>s should
report the initial navigation requested by the parent document, but not
subsequent navigations.
The problem is
m_documentLoader->frameLoader()->stateMachine()->committingFirstRealLoad(),
consider:
Case A: iframe mark up with src="", then changed to src=R2 via script.
Case B: iframe mark up with src=R1, then changed to src=R2 via script.
In current loader implementation, stateMachine of frameLoader is in state
"CommittedFirstRealLoad" at the time just before loading R2 for both A and B. (A
load "about:blank" firstly), so R2 won't be populated.

In latest editor draft of Resource Timing[1], section 4.2 example 3 describes
case A, it said "about:blank" and R2 should be populated (Personally, I don't
think populating "about:blank" make sense, especially un-touch network at all).

To populate R2 in case A, and avoid touch the state machine, I think we may need
a new flag in FrameLoader, named like "LoadedNonEmptyDocument", set it true when
state machine advanced to "CommittedFirstRealLoad" for a non-empty load.

is it practical?

thanks
Pan

[1]
https://dvcs.w3.org/hg/webperf/raw-file/tip/specs/ResourceTiming/Overview.html

[James Simonsen, 2013-04-26 18:45:33]

On 2013/04/25 12:40:51, Pan wrote:
>
https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
> File Source/core/loader/cache/CachedResourceLoader.cpp (right):
> 
>
https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
> Source/core/loader/cache/CachedResourceLoader.cpp:489: // <iframe>s should
> report the initial navigation requested by the parent document, but not
> subsequent navigations.
> The problem is
> m_documentLoader->frameLoader()->stateMachine()->committingFirstRealLoad(),
> consider:
> Case A: iframe mark up with src="", then changed to src=R2 via script.
> Case B: iframe mark up with src=R1, then changed to src=R2 via script.
> In current loader implementation, stateMachine of frameLoader is in state
> "CommittedFirstRealLoad" at the time just before loading R2 for both A and B.
(A
> load "about:blank" firstly), so R2 won't be populated.
> 
> In latest editor draft of Resource Timing[1], section 4.2 example 3 describes
> case A, it said "about:blank" and R2 should be populated (Personally, I don't
> think populating "about:blank" make sense, especially un-touch network at
all).

Agreed. I don't like showing about:blank either. Do you want to raise this on
the mailing list?

> To populate R2 in case A, and avoid touch the state machine, I think we may
need
> a new flag in FrameLoader, named like "LoadedNonEmptyDocument", set it true
when
> state machine advanced to "CommittedFirstRealLoad" for a non-empty load.
> 
> is it practical?

Seems fine to me. You might want to run it by Nate.

[Pan, 2013-05-16 13:09:31]

Hi James and Tony,

Since mmenke land the patch in https://codereview.chromium.org/14625012/, this
CL should ready to move on, while, I noticed another issue that lead to layout
test flaky.

Class ResourceLoadTiming in
webcore(third_party/WebKit/Source/core/platform/network/ResourceLoadTiming.h)
has a base requestTime with type "double", others are millisecond deltas with
type "int", such as dnsStart, so in glue(webkit/glue/weburlloader_impl.cc), we
had to calculate delta between the real dnsStart and its base time
request_start, and round to a int value in millisecond resolution, and lost the
precision of high resolution time. Especially, when redirect is considered, the
"round" even cause a overlap, for example: A network fetch got redirect response
R1 and final response R2. R1's receive_headers_end may be round up to a little
bigger value, even bigger than R2's request_start, as R2's
request_start(request_time in blink)is a base never be rounded.
So I suggest we adopt microsecond resolution for deltas in ResourceLoadTiming,
and a change corresponding glue, how do you think of it? (shall we consider
16bit int? then overflow is a problem).

thanks!
Pan

[Pan, 2013-05-20 23:26:01]

On 2013/05/16 13:09:31, Pan wrote:
> Hi James and Tony,
> 
> Since mmenke land the patch in https://codereview.chromium.org/14625012/, this
> CL should ready to move on, while, I noticed another issue that lead to layout
> test flaky.
> 
> Class ResourceLoadTiming in
> webcore(third_party/WebKit/Source/core/platform/network/ResourceLoadTiming.h)
> has a base requestTime with type "double", others are millisecond deltas with
> type "int", such as dnsStart, so in glue(webkit/glue/weburlloader_impl.cc), we
> had to calculate delta between the real dnsStart and its base time
> request_start, and round to a int value in millisecond resolution, and lost
the
> precision of high resolution time. Especially, when redirect is considered,
the
> "round" even cause a overlap, for example: A network fetch got redirect
response
> R1 and final response R2. R1's receive_headers_end may be round up to a little
> bigger value, even bigger than R2's request_start, as R2's
> request_start(request_time in blink)is a base never be rounded.
> So I suggest we adopt microsecond resolution for deltas in ResourceLoadTiming,
> and a change corresponding glue, how do you think of it? (shall we consider
> 16bit int? then overflow is a problem).
> 
> thanks!
> Pan

In addition, Inspector also uses ResourceLoadTiming, a small change is needed
there. I didn't see others according to code search. 
any concern? :)

thanks
Pan

[James Simonsen, 2013-05-20 23:31:37]

I agree that it's bad to lose the resolution. In extreme cases, this can result
in negative values being reported, which has been known to throw exceptions on
sites. My personal opinion is that we should just use doubles instead of trying
to save a few dozen bytes per resource.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File LayoutTests/http/tests/w3c/webperf/resources/multi_redirect.php (right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/resources/multi_redirect.php:2: $step =
$_GET["step"] ? $_GET["step"]  : 1;
too many spaces before :

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html
(right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html:31:
test_greater_or_equals(entry.fetchStart - 3000, 0, "fetchStart should be 3 secs
later than navigationStart");
I think it'd be easier to read if the 3000 was the second arg instead of 0.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html:46:
destUrl += 'pageOrigin=' + 'http://' +pageOrigin;
Spaces around +.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html:48:
destUrl += '&timingAllow=' + 0;
Just put 0 in the string.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html
(right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:21:
setTimeout(onload_test, 1000);
I don't see why this is needed. Everything we test should already be populated.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:31:
test_greater_or_equals(entry.redirectEnd - 3000, entry.redirectStart,
"redirectEnd should be 3 secs later than redirectStart");
Again, move 3000 to the second arg, then the code will match the description.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:47:
destUrl += '&crossOrigin=' + 'http://' +crossOrigin;
Spaces.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:48:
destUrl += '&timingAllow=' + 1;
Inline 1.

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/Resour...
File Source/core/loader/ResourceLoadNotifier.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/Resour...
Source/core/loader/ResourceLoadNotifier.cpp:109: // Report WebTiming for all
frames.
frames -> requests

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.h (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.h:174: HashMap<CachedResource*,
ResourceTimingInfo> m_resourceTimingInfoMap;
These have complex objects in them, like vectors. I don't think we should copy
those as this map is resized. Instead, this should own a pointer to
ResourceTimingInfo.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:194: bool shouldReportDetails = true;
For me, this function would read much easier if there were 2 bools: hadRedirect
and hadCrossOriginRedirect. And then just handle each of the 3 cases.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:195: Vector<ResourceResponse> redirectChain =
info.redirectChain();
const&

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:198: if (false == (shouldReportDetails =
passesTimingAllowCheck(redirectChain[i], initiatorDocument)))
Separate lines please.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:206: ResourceLoadTiming* loadTiming =
redirectChain.last().resourceLoadTiming();
loadTiming -> lastRedirectTiming

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:212: lastRedirectEndTime =
loadTiming->requestTime;
Isn't it a bug if receiveHeadersEnd isn't set? We're still supposed to report
how long it took to look things up in the cache. We should file a bug and make
this a FIXME.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
File Source/core/page/ResourceTimingInfo.h (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
Source/core/page/ResourceTimingInfo.h:64: m_loadFinishTime=
info.m_loadFinishTime;
Space before =.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
Source/core/page/ResourceTimingInfo.h:71: AtomicString initiatorType() const {
return m_type; }
These should all return const& for complex types.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
Source/core/page/ResourceTimingInfo.h:87: 
No blank lines here.

[Pan, 2013-05-21 01:15:00]

On 2013/05/20 23:31:37, James Simonsen wrote:
> I agree that it's bad to lose the resolution. In extreme cases, this can
result
> in negative values being reported, which has been known to throw exceptions on
> sites. My personal opinion is that we should just use doubles instead of
trying
> to save a few dozen bytes per resource.
> 
Why not? just like DocumentLoadTiming, I'd like to patch it in another CL
firstly.

thanks
Pan

[Pan, 2013-06-03 10:17:34]

Hi James and Tony,

This patch was refined and rebased, now ready to review.
Two things should noted:
1, New test case won't pass before network time ticks expose in content shell.
https://codereview.chromium.org/16324002/
2, It seems build bot become smarter, some w3c style test case won't be applied
as they have similarity problem. I've no idea about this. :(

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File LayoutTests/http/tests/w3c/webperf/resources/multi_redirect.php (right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/resources/multi_redirect.php:2: $step =
$_GET["step"] ? $_GET["step"]  : 1;
On 2013/05/20 23:31:37, James Simonsen wrote:
> too many spaces before :

done.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html
(right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain.html:31:
test_greater_or_equals(entry.fetchStart - 3000, 0, "fetchStart should be 3 secs
later than navigationStart");
On 2013/05/20 23:31:37, James Simonsen wrote:
> I think it'd be easier to read if the 3000 was the second arg instead of 0.
Agree, done.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
File
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html
(right):

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:21:
setTimeout(onload_test, 1000);
On 2013/05/20 23:31:37, James Simonsen wrote:
> I don't see why this is needed. Everything we test should already be
populated.

yep, removed.

https://codereview.chromium.org/13912021/diff/14001/LayoutTests/http/tests/w3...
LayoutTests/http/tests/w3c/webperf/submission/Intel/resource-timing/test_resource_timing_cross_origin_redirect_chain_allow_timing.html:31:
test_greater_or_equals(entry.redirectEnd - 3000, entry.redirectStart,
"redirectEnd should be 3 secs later than redirectStart");
On 2013/05/20 23:31:37, James Simonsen wrote:
> Again, move 3000 to the second arg, then the code will match the description.

done.

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/Resour...
File Source/core/loader/ResourceLoadNotifier.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/Resour...
Source/core/loader/ResourceLoadNotifier.cpp:109: // Report WebTiming for all
frames.
On 2013/05/20 23:31:37, James Simonsen wrote:
> frames -> requests
yep, done

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.h (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.h:174: HashMap<CachedResource*,
ResourceTimingInfo> m_resourceTimingInfoMap;
On 2013/05/20 23:31:37, James Simonsen wrote:
> These have complex objects in them, like vectors. I don't think we should copy
> those as this map is resized. Instead, this should own a pointer to
> ResourceTimingInfo.

Agree, done

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:194: bool shouldReportDetails = true;
On 2013/05/20 23:31:37, James Simonsen wrote:
> For me, this function would read much easier if there were 2 bools:
hadRedirect
> and hadCrossOriginRedirect. And then just handle each of the 3 cases.

I seperated the non-redirect case and redirect-case, hope it read better.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:195: Vector<ResourceResponse> redirectChain =
info.redirectChain();
On 2013/05/20 23:31:37, James Simonsen wrote:
> const&

yep done.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:206: ResourceLoadTiming* loadTiming =
redirectChain.last().resourceLoadTiming();
On 2013/05/20 23:31:37, James Simonsen wrote:
> loadTiming -> lastRedirectTiming

done.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Performa...
Source/core/page/Performance.cpp:212: lastRedirectEndTime =
loadTiming->requestTime;
On 2013/05/20 23:31:37, James Simonsen wrote:
> Isn't it a bug if receiveHeadersEnd isn't set? We're still supposed to report
> how long it took to look things up in the cache. We should file a bug and make
> this a FIXME.

Not a bug, this should be removed once after mmenke's patch landed.
Now removed.

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
File Source/core/page/ResourceTimingInfo.h (right):

https://codereview.chromium.org/13912021/diff/14001/Source/core/page/Resource...
Source/core/page/ResourceTimingInfo.h:71: AtomicString initiatorType() const {
return m_type; }
On 2013/05/20 23:31:37, James Simonsen wrote:
> These should all return const& for complex types.

yep, fix all these.

[James Simonsen, 2013-06-04 01:13:04]

Once these nitsn are fixed, I think this looks good from my end. You'll need
owner approval for Blink.

https://codereview.chromium.org/13912021/diff/52001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.cpp:763: HashMap<CachedResource*,
RefPtr<ResourceTimingInfo> >::iterator infoIter =
m_resourceTimingInfoMap.find(resource);
Can you make this a typedef in the .h file? I should've done that from the
beginning.

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/Performance.cpp:212: RefPtr<PerformanceEntry> entry =
PerformanceResourceTiming::create(info, initiatorDocument, startTime,
allowTimingFetch);
Why not move this to populateResourceTimingEntry? It happens in both cases.

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/Performance.cpp:234: void
Performance::populateResourceTimingEntry(PassRefPtr<PerformanceEntry> entry)
Maybe call this addResourceTimingToBuffer()?

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/PerformanceResourceTiming.cpp:78: if (!m_lastRedirectEndTime ||
!m_allowTimingRedirect)
m_allowRedirectDetails sounds better.

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/PerformanceResourceTiming.cpp:102: if (!m_allowTimingFetch)
m_allowTimingDetails sounds better.

[Pan, 2013-06-04 02:48:34]

thanks for James review.

@tonyg and @japhet,
could you please help review this :)

thanks!
Pan

https://codereview.chromium.org/13912021/diff/52001/Source/core/loader/cache/...
File Source/core/loader/cache/CachedResourceLoader.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/loader/cache/...
Source/core/loader/cache/CachedResourceLoader.cpp:763: HashMap<CachedResource*,
RefPtr<ResourceTimingInfo> >::iterator infoIter =
m_resourceTimingInfoMap.find(resource);
On 2013/06/04 01:13:04, James Simonsen wrote:
> Can you make this a typedef in the .h file? I should've done that from the
> beginning.
yep, done.

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
File Source/core/page/Performance.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/Performance.cpp:212: RefPtr<PerformanceEntry> entry =
PerformanceResourceTiming::create(info, initiatorDocument, startTime,
allowTimingFetch);
On 2013/06/04 01:13:04, James Simonsen wrote:
> Why not move this to populateResourceTimingEntry? It happens in both cases.
they are overload functions to distinguish non-redirect and redirect cases, I
thought it would be better to leave them close to code that prepare params :)

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/Performance.cpp:234: void
Performance::populateResourceTimingEntry(PassRefPtr<PerformanceEntry> entry)
On 2013/06/04 01:13:04, James Simonsen wrote:
> Maybe call this addResourceTimingToBuffer()?

yes, thanks!

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
File Source/core/page/PerformanceResourceTiming.cpp (right):

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/PerformanceResourceTiming.cpp:78: if (!m_lastRedirectEndTime ||
!m_allowTimingRedirect)
On 2013/06/04 01:13:04, James Simonsen wrote:
> m_allowRedirectDetails sounds better.

yep, thanks!

https://codereview.chromium.org/13912021/diff/52001/Source/core/page/Performa...
Source/core/page/PerformanceResourceTiming.cpp:102: if (!m_allowTimingFetch)
On 2013/06/04 01:13:04, James Simonsen wrote:
> m_allowTimingDetails sounds better.
yep, thanks!

[Pan, 2013-06-05 02:15:02]

@tonyg, could you please review the web timing part? 
and @japhet could you please review the loader part? :)

thanks!
Pan

[Nate Chapin, 2013-06-05 16:26:45]

loader changes are fine.

[Pan, 2013-06-06 23:28:12]

@tonyg, your comment is appreciated :)

thanks!
Pan

[tonyg, 2013-06-07 17:16:44]

lgtm

[commit-bot: I haz the power, 2013-06-07 23:01:33]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/pan.deng@intel.com/13912021/54010

[commit-bot: I haz the power, 2013-06-07 23:01:38]

Failed to apply patch for Source/core/loader/cache/CachedResourceLoader.cpp:
While running patch -p1 --forward --force --no-backup-if-mismatch;
  patching file Source/core/loader/cache/CachedResourceLoader.cpp
  Hunk #2 FAILED at 597.
  Hunk #3 succeeded at 818 (offset 38 lines).
  1 out of 3 hunks FAILED -- saving rejects to file
Source/core/loader/cache/CachedResourceLoader.cpp.rej

Patch:       Source/core/loader/cache/CachedResourceLoader.cpp
Index: Source/core/loader/cache/CachedResourceLoader.cpp
diff --git a/Source/core/loader/cache/CachedResourceLoader.cpp
b/Source/core/loader/cache/CachedResourceLoader.cpp
index
b5ca77c14353e4b5fd59767861482c1cb8e02bd3..4702db87be3b853cfcbfda34a090701fc4b26b51
100644
--- a/Source/core/loader/cache/CachedResourceLoader.cpp
+++ b/Source/core/loader/cache/CachedResourceLoader.cpp
@@ -57,6 +57,7 @@
 #include "core/page/DOMWindow.h"
 #include "core/page/Frame.h"
 #include "core/page/Performance.h"
+#include "core/page/ResourceTimingInfo.h"
 #include "core/page/Settings.h"
 #include "core/platform/Logging.h"
 #include "weborigin/SecurityOrigin.h"
@@ -596,18 +597,17 @@ CachedResourceHandle<CachedResource>
CachedResourceLoader::loadResource(CachedRe
 
 void CachedResourceLoader::storeResourceTimingInitiatorInformation(const
CachedResourceHandle<CachedResource>& resource, const CachedResourceRequest&
request)
 {
-    CachedResourceInitiatorInfo info = request.initiatorInfo();
-    info.startTime = monotonicallyIncreasingTime();
+    RefPtr<ResourceTimingInfo> info =
ResourceTimingInfo::create(request.initiatorInfo().name,
monotonicallyIncreasingTime());
 
     if (resource->type() == CachedResource::MainResource) {
         // <iframe>s should report the initial navigation requested by the
parent document, but not subsequent navigations.
         if (frame()->ownerElement() &&
!frame()->ownerElement()->loadedNonEmptyDocument()) {
-            info.name = frame()->ownerElement()->localName();
-            m_initiatorMap.add(resource.get(), info);
+            info->setInitiatorType(frame()->ownerElement()->localName());
+            m_resourceTimingInfoMap.add(resource.get(), info);
             frame()->ownerElement()->didLoadNonEmptyDocument();
         }
     } else {
-        m_initiatorMap.add(resource.get(), info);
+        m_resourceTimingInfoMap.add(resource.get(), info);
     }
 }
 
@@ -779,22 +779,32 @@ CachePolicy
CachedResourceLoader::cachePolicy(CachedResource::Type type) const
     return CachePolicyVerify;
 }
 
+void CachedResourceLoader::redirectReceived(CachedResource* resource, const
ResourceResponse& redirectResponse)
+{
+    ResourceTimingInfoMap::iterator it =
m_resourceTimingInfoMap.find(resource);
+    if (it != m_resourceTimingInfoMap.end())
+        it->value->addRedirect(redirectResponse);
+}
+
 void CachedResourceLoader::loadDone(CachedResource* resource)
 {
     RefPtr<DocumentLoader> protectDocumentLoader(m_documentLoader);
     RefPtr<Document> protectDocument(m_document);
 
     if (resource && resource->response().isHTTP() &&
((!resource->errorOccurred() && !resource->wasCanceled()) ||
resource->response().httpStatusCode() == 304)) {
-        HashMap<CachedResource*, CachedResourceInitiatorInfo>::iterator
initiatorIt = m_initiatorMap.find(resource);
-        if (initiatorIt != m_initiatorMap.end()) {
+        ResourceTimingInfoMap::iterator it =
m_resourceTimingInfoMap.find(resource);
+        if (it != m_resourceTimingInfoMap.end()) {
             ASSERT(document());
             Document* initiatorDocument = document();
             if (resource->type() == CachedResource::MainResource)
                 initiatorDocument = document()->parentDocument();
             ASSERT(initiatorDocument);
-            const CachedResourceInitiatorInfo& info = initiatorIt->value;
-           
initiatorDocument->domWindow()->performance()->addResourceTiming(info.name,
initiatorDocument, resource->resourceRequest(), resource->response(),
info.startTime, resource->loadFinishTime());
-            m_initiatorMap.remove(initiatorIt);
+            RefPtr<ResourceTimingInfo> info = it->value;
+            info->setInitialRequest(resource->resourceRequest());
+            info->setFinalResponse(resource->response());
+            info->setLoadFinishTime(resource->loadFinishTime());
+           
initiatorDocument->domWindow()->performance()->addResourceTiming(*info,
initiatorDocument);
+            m_resourceTimingInfoMap.remove(it);
         }
     }

[commit-bot: I haz the power, 2013-06-08 00:58:23]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/pan.deng@intel.com/13912021/96001

[commit-bot: I haz the power, 2013-06-08 07:35:14]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/pan.deng@intel.com/13912021/110001

[commit-bot: I haz the power, 2013-06-09 03:06:25]

Change committed as 152077