Bug 58354 – [Navigation Timing] Use monotonicallyIncreasingTime() instead of currentTime()

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore Misc.

[Tony Gentilcore]

Currently our Navigation Timing implementation stores wall time values internally for each mark. We should consider instead storing a single absolute and offsets. Then do the addition in the getter to convert to a wall time. The idea is to prevent bad data when the wall time changes (ntp, leap second, skew adjust, etc).

https://bugs.webkit.org/show_bug.cgi?id=53305 is slightly related.

[Tony Gentilcore]

Using a monotonic clock instead of a wall clock is now discussed in the spec:
http://dvcs.w3.org/hg/webperf/rev/779738076f74

[James Simonsen]

Created attachment 103328 [details]
Patch

[Tony Gentilcore]

Comment on attachment 103328 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=103328&action=review

This is great stuff!

> Source/WebCore/loader/DocumentLoadTiming.h:61
> +    double monotonicResponseEnd;

It makes me slightly sad that we need this. Can we instead assume that if a monotonicReferenceStartTime is provided, then responseEnd has a monotonic value?

> Source/WebCore/page/PerformanceTiming.cpp:-53
> -static double getPossiblySkewedTimeInKnownRange(double skewedTime, double lowerBound, double upperBound)

So nice to see this badness gone!!

> Source/WebCore/platform/network/ResourceLoadTiming.h:46
> +        timing->monotonicRequestTime = monotonicRequestTime;

Since this is a platform API, I want to be a little bit careful with it.

Is it really necessary to have a requestTime and monotonicRequestTime? I don't understand why we can't put the monotonic version into requestTime. If this is being overloaded to determine whether the platform provided monotonic times, could we instead add a boolean timesAreMonotonicallyIncreasing or something? If all ports used monotonic, could we get rid of this? Perhaps we can just file bugs and not leave a trail in the API?

[Pavel Feldman]

Comment on attachment 103328 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=103328&action=review

> Source/WebCore/loader/MainResourceLoader.cpp:485
> +        documentLoader()->timing()->responseEnd = finishTime;

I don't think you should mutate WebKit-provided values from within the WebCore even for convenience. (I realize that both timing and finishTime originate from WebKit). You've done the job for the main resource loader, but same timing struct + finishTime are provided for subresources.

>> Source/WebCore/platform/network/ResourceLoadTiming.h:46
>> +        timing->monotonicRequestTime = monotonicRequestTime;
> 
> Since this is a platform API, I want to be a little bit careful with it.
> 
> Is it really necessary to have a requestTime and monotonicRequestTime? I don't understand why we can't put the monotonic version into requestTime. If this is being overloaded to determine whether the platform provided monotonic times, could we instead add a boolean timesAreMonotonicallyIncreasing or something? If all ports used monotonic, could we get rid of this? Perhaps we can just file bugs and not leave a trail in the API?

ResourceLoadTiming data originates from the port (WebKit). It does not really matter whether we use currentTime or monotonicTime in WebCore since it is likely that port's time will differ anyways. In chromium's case (and Chromium is the only port providing this data), the time is taken in the network stack, in the browser process. So I'd suggest that we leave it as is and carefully sync it with the WebCore timings where these two intersect.

> Source/WebCore/platform/network/ResourceLoadTiming.h:96
> +    int responseEnd;

does not belong here as per comment above.

[James Simonsen]

(In reply to comment #3)
> (From update of attachment 103328 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=103328&action=review
> 
> This is great stuff!
> 
> > Source/WebCore/loader/DocumentLoadTiming.h:61
> > +    double monotonicResponseEnd;
> 
> It makes me slightly sad that we need this. Can we instead assume that if a monotonicReferenceStartTime is provided, then responseEnd has a monotonic value?

This is solving a slightly different problem.

For the record, monotonicReferenceStartTime is always available, because it's set in WebCore.

responseEnd has two possible origins. Normally, it comes from the platform as finishTime, which is currently spec'd to return a wall time. However, sometimes didFinishLoading(0) is called, like when the user presses stop. In that case, we fall back to whenever the last byte was received, or just use the current time if we have no better estimate. In these latter cases, we'd prefer to use the monotonic clock. I need some way of knowing which time-offset was used to determine responseEnd. I decided a separate variable was clearest.

> > Source/WebCore/page/PerformanceTiming.cpp:-53
> > -static double getPossiblySkewedTimeInKnownRange(double skewedTime, double lowerBound, double upperBound)
> 
> So nice to see this badness gone!!
> 
> > Source/WebCore/platform/network/ResourceLoadTiming.h:46
> > +        timing->monotonicRequestTime = monotonicRequestTime;
> 
> Since this is a platform API, I want to be a little bit careful with it.
> 
> Is it really necessary to have a requestTime and monotonicRequestTime? I don't understand why we can't put the monotonic version into requestTime. If this is being overloaded to determine whether the platform provided monotonic times, could we instead add a boolean timesAreMonotonicallyIncreasing or something? If all ports used monotonic, could we get rid of this? Perhaps we can just file bugs and not leave a trail in the API?

requestTime is now redundant. I'd like to deprecate it and always use monotonic times. I was afraid of changing the meaning of an existing field though, so I just added a new one and hoped to delete the old one later.

[James Simonsen]

(In reply to comment #4)
> (From update of attachment 103328 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=103328&action=review
> 
> > Source/WebCore/loader/MainResourceLoader.cpp:485
> > +        documentLoader()->timing()->responseEnd = finishTime;
> 
> I don't think you should mutate WebKit-provided values from within the WebCore even for convenience. (I realize that both timing and finishTime originate from WebKit). You've done the job for the main resource loader, but same timing struct + finishTime are provided for subresources.

This is actually a different timing(). It's a DocumentLoadTiming and originates in WebCore. This is the only place where DocumentLoadTiming.responseEnd is set.

I agree it's awkward that we shove finishTime into this WebCore struct. My long term goal was to deprecate finishTime and have everyone just use ResourceLoadTiming. Is that a reasonable goal?

> >> Source/WebCore/platform/network/ResourceLoadTiming.h:46
> >> +        timing->monotonicRequestTime = monotonicRequestTime;
> > 
> > Since this is a platform API, I want to be a little bit careful with it.
> > 
> > Is it really necessary to have a requestTime and monotonicRequestTime? I don't understand why we can't put the monotonic version into requestTime. If this is being overloaded to determine whether the platform provided monotonic times, could we instead add a boolean timesAreMonotonicallyIncreasing or something? If all ports used monotonic, could we get rid of this? Perhaps we can just file bugs and not leave a trail in the API?
> 
> ResourceLoadTiming data originates from the port (WebKit). It does not really matter whether we use currentTime or monotonicTime in WebCore since it is likely that port's time will differ anyways. In chromium's case (and Chromium is the only port providing this data), the time is taken in the network stack, in the browser process. So I'd suggest that we leave it as is and carefully sync it with the WebCore timings where these two intersect.

It might help to see the Chrome change that goes with this. I can send you that CL too.

monotonicTime is TimeTicks. WebCore now has access to TimeTicks via monotonicallyIncreasingTime(). We exposed this to fix all of the clock skew problems we have when the user's wall clock is updated.

Since the clock might be adjusted between when the Document's referenceTime is set to currentTime() and when timing.base_time is set in the network stack, we need to always use the monotonic clock to determine when the resource loaded relative to the referenceTime. So, the network stack should now return base_ticks instead of base_time.

Really, I want everything coming from the port to be in monotonic times. The only time I ever want currentTime() is for setting the Document's referenceTime.

> 
> > Source/WebCore/platform/network/ResourceLoadTiming.h:96
> > +    int responseEnd;
> 
> does not belong here as per comment above.

We need some way to get the TimeTicks when the response finished. I didn't want to change the didFinishLoading() API to pass in TimeTicks, since then all of the other ports would need to be updated.

[Pavel Feldman]

> I agree it's awkward that we shove finishTime into this WebCore struct. My long term goal was to deprecate finishTime and have everyone just use ResourceLoadTiming. Is that a reasonable goal?

I don't think you can fetch appropriate ResourceLoadTiming instance upon receiving didReceiveResponse at all times. You can do that for main resource, but not necessarily for subresources. Has that changed?

> It might help to see the Chrome change that goes with this. I can send you that CL too.

Sure, send it in.

[James Simonsen]

P.S. Thanks to both of you for taking the time to review this.

(In reply to comment #7)
> > I agree it's awkward that we shove finishTime into this WebCore struct. My long term goal was to deprecate finishTime and have everyone just use ResourceLoadTiming. Is that a reasonable goal?
> 
> I don't think you can fetch appropriate ResourceLoadTiming instance upon receiving didReceiveResponse at all times. You can do that for main resource, but not necessarily for subresources. Has that changed?

Probably not. I haven't actually looked into doing it yet. It was just my hope.

> 
> > It might help to see the Chrome change that goes with this. I can send you that CL too.
> 
> Sure, send it in.

http://codereview.chromium.org/7602023/

I didn't want to publish it yet, since it's not ready to go in until this WebKit change is submitted.

[James Simonsen]

Created attachment 103733 [details]
Patch

[Pavel Feldman]

Comment on attachment 103733 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=103733&action=review

Looks almost good.

> Source/WebCore/dom/DocumentTiming.h:40
> +        , referenceStartTime(currentTime())

This might be not the best place to initialize these: document is created when the provisional load commits. You could do a static lazy getter on ResourceLoadTiming instead that would init those to emphasize that it does not matter whether the time converted is before or after this initialization.

Also, it would be nice to see a comment explaining conversion taking place there. The one that would explain how TimeTicks correlate with monotonicallyIncreasingTime in case of Chromium so that other ports could jump in.

> Source/WebCore/inspector/InspectorInstrumentation.cpp:512
> +    double finishTime = 0.0;

You should not do anything unless either of the agents below is activated.

> Source/WebCore/inspector/InspectorInstrumentation.cpp:516
> +            finishTime = documentTiming->referenceStartTime + monotonicFinishTime - documentTiming->monotonicReferenceStartTime;

Please add a FIXME suggesting that this conversion should be pushed into the inspector itself.

> Source/WebCore/inspector/InspectorResourceAgent.cpp:126
> +    timingObject->setNumber("requestTime", referenceTime + timing.requestTime);

Could you encapsulate this into the ResourceLoadTiming convenience getter?

> Source/WebCore/inspector/InspectorResourceAgent.cpp:167
> +        responseObject->setObject("timing", buildObjectForTiming(*response.resourceLoadTiming(), referenceTime));

That way you won't need to do this.

> Source/WebCore/inspector/InspectorResourceAgent.cpp:200
> +        referenceTime = timing->referenceStartTime - timing->monotonicReferenceStartTime;

And all this math syncing WebCore and platform time would live in a single place...

> Source/WebCore/inspector/InspectorResourceAgent.cpp:246
> +    m_frontend->requestWillBeSent(resourceId, m_pageAgent->frameId(loader->frame()), m_pageAgent->loaderId(loader), loader->url().string(), buildObjectForResourceRequest(request), currentTime(), initiatorObject, callStackValue, buildObjectForResourceResponse(redirectResponse, GetReferenceTimeFromLoader(loader)));

Like here, in case of the provisional load you will be using timing struct from the current document.

> Source/WebCore/page/PerformanceTiming.cpp:370
> +    return toIntegerMilliseconds(timing->referenceStartTime + monotonicSeconds - timing->monotonicReferenceStartTime);

Same math again.

[James Simonsen]

You bring up some really good points that revealed a couple of deficiencies in the spec. I've raised these with the WG and updated part of the code. One is still open, so I'll address that tomorrow.

(In reply to comment #10)
> (From update of attachment 103733 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=103733&action=review
> 
> Looks almost good.
> 
> > Source/WebCore/dom/DocumentTiming.h:40
> > +        , referenceStartTime(currentTime())
> 
> This might be not the best place to initialize these: document is created when the provisional load commits. You could do a static lazy getter on ResourceLoadTiming instead that would init those to emphasize that it does not matter whether the time converted is before or after this initialization.

This is a good point. The Navigation Timing spec defines where the monotonic reference should be for documents. It's supposed to be at navigation start. I've fixed that for the main document.

However, there's still an open issue with iframes. Right now, it's spec'd that they get their own reference time, but that's bad for users, since they won't be able to plot iframes on the same timeline as the main document. I'm waiting to hear back on this.

> Also, it would be nice to see a comment explaining conversion taking place there. The one that would explain how TimeTicks correlate with monotonicallyIncreasingTime in case of Chromium so that other ports could jump in.

Done.

> > Source/WebCore/inspector/InspectorInstrumentation.cpp:512
> > +    double finishTime = 0.0;
> 
> You should not do anything unless either of the agents below is activated.

Done.

> > Source/WebCore/inspector/InspectorInstrumentation.cpp:516
> > +            finishTime = documentTiming->referenceStartTime + monotonicFinishTime - documentTiming->monotonicReferenceStartTime;
> 
> Please add a FIXME suggesting that this conversion should be pushed into the inspector itself.

Done.

> > Source/WebCore/inspector/InspectorResourceAgent.cpp:126
> > +    timingObject->setNumber("requestTime", referenceTime + timing.requestTime);
> 
> Could you encapsulate this into the ResourceLoadTiming convenience getter?

That would've been great if the reference time was in ResourceLoadTiming, but since we have to reference against the main document load (see below), it's still ugly. :(

> > Source/WebCore/inspector/InspectorResourceAgent.cpp:246
> > +    m_frontend->requestWillBeSent(resourceId, m_pageAgent->frameId(loader->frame()), m_pageAgent->loaderId(loader), loader->url().string(), buildObjectForResourceRequest(request), currentTime(), initiatorObject, callStackValue, buildObjectForResourceResponse(redirectResponse, GetReferenceTimeFromLoader(loader)));
> 
> Like here, in case of the provisional load you will be using timing struct from the current document.

Another good point. This was not clearly defined in the spec, so I asked for clarification. The decision is that resources are supposed to use the same reference time as the main document so that they can appear on the same timeline.

[James Simonsen]

Created attachment 104007 [details]
WIP Patch

[James Simonsen]

Created attachment 104127 [details]
Patch

[Gyuyoung Kim]

Comment on attachment 104127 [details]
Patch

Attachment 104127 [details] did not pass efl-ews (efl):
Output: http://queues.webkit.org/results/9403543

[Early Warning System Bot]

Comment on attachment 104127 [details]
Patch

Attachment 104127 [details] did not pass qt-ews (qt):
Output: http://queues.webkit.org/results/9407505

[WebKit Review Bot]

Comment on attachment 104127 [details]
Patch

Attachment 104127 [details] did not pass mac-ews (mac):
Output: http://queues.webkit.org/results/9404516

[James Simonsen]

Created attachment 104142 [details]
Patch

[James Simonsen]

Would you guys mind taking another look at this? It's changed significantly since the initial patch.

[Tony Gentilcore]

Comment on attachment 104142 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=104142&action=review

This LGTM, but it would be nice if pfeldman took another pass.

> Source/WebCore/CMakeLists.txt:891
> +    loader/DocumentLoadTiming.cpp

I think we do ascii sorting (caps before lower)

[Pavel Feldman]

Comment on attachment 104142 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=104142&action=review

Looks good to me. Sorry guys, I was sure I posted my review two days ago saying inspector part was fine by me and suggesting that Tony takes a look at the web timing. Opened this review link now to find my comments pending submit...

>> Source/WebCore/CMakeLists.txt:891
>> +    loader/DocumentLoadTiming.cpp
> 
> I think we do ascii sorting (caps before lower)

We do.

> Source/WebCore/loader/DocumentLoadTiming.cpp:63
> +    Document* rootDocument = frame->tree()->top(true)->document();

Nit: I got used to the frame->page()->mainFrame()->document() form.

> Source/WebCore/loader/DocumentLoadTiming.cpp:64
> +    if (rootDocument && this != rootDocument->loader()->timing())

Why do you need the second check?

> Source/WebCore/loader/MainResourceLoader.cpp:587
> +    documentLoader()->timing()->setFetchStart();

Nit: markFetchStart?

[James Simonsen]

Created attachment 105130 [details]
Patch

[satish kambala]

Thanks folks for working on this fix.

I hit this bug almost always in Chrome on Linux.
https://bugs.webkit.org/show_bug.cgi?id=53305

It will be great to have this fixed. My 2 cents to expedite this.

[satish kambala]

I faced this issue when redirection is present. In almost all the cases, I noticed that responseEnd < responseStart. In some cases responseEnd matched with requestStart. Please verify if there is anything specific to responseEnd or it might be same clock issue that is getting hit when the response comes back. Attached a sample window.performance.timing object that has this bug.

connectEnd: 1317943802191
connectStart: 1317943802191
domComplete: 1317943803381
domContentLoadedEventEnd: 1317943802381
domContentLoadedEventStart: 1317943802381
domInteractive: 1317943802381
domLoading: 1317943802201
domainLookupEnd: 1317943802191
domainLookupStart: 1317943802191
fetchStart: 1317943802191
loadEventEnd: 1317943803388
loadEventStart: 1317943803381
navigationStart: 1317943801958
redirectEnd: 1317943802191
redirectStart: 1317943801958
requestStart: 1317943802193
responseEnd: 1317943802193
responseStart: 1317943802311
secureConnectionStart: 0
unloadEventEnd: 1317943802193
unloadEventStart: 1317943802193

[James Simonsen]

(In reply to comment #23)
> I faced this issue when redirection is present. In almost all the cases, I noticed that responseEnd < responseStart. In some cases responseEnd matched with requestStart. Please verify if there is anything specific to responseEnd or it might be same clock issue that is getting hit when the response comes back. Attached a sample window.performance.timing object that has this bug.

I suspect it's the same issue. I wasn't able to reproduce this locally. By any chance are you on Windows? That has the most clock issues.

I notice that the clamping done in WebKit to ensure that the times are sane only affects the lower bound. We should really clamp both sides.

Sadly, the Chrome side of this fix still is waiting for review. I'll ping it again, but it's looking unlikely for M16 now. :(

Given that, I'll upload a patch that clamps both sides as mentioned above. That should at least get rid of the negative times, but it's not as accurate as the proper solution.

[satish kambala]

Thanks for the update James. I noticed this on Ubuntu and Mac.

[James Simonsen]

Created attachment 119047 [details]
Patch for landing

[WebKit Review Bot]

Comment on attachment 119047 [details]
Patch for landing

Clearing flags on attachment: 119047

Committed r102696: <http://trac.webkit.org/changeset/102696>

[WebKit Review Bot]

All reviewed patches have been landed.  Closing bug.

[Vsevolod Vlasov]

(In reply to comment #27)
> (From update of attachment 119047 [details])
> Clearing flags on attachment: 119047
> 
> Committed r102696: <http://trac.webkit.org/changeset/102696>

This patch broke (at least) inspector's network panel timeline.
Should we revert it or there is a quick fix?

[James Simonsen]

(In reply to comment #29)
> (In reply to comment #27)
> > (From update of attachment 119047 [details] [details])
> > Clearing flags on attachment: 119047
> > 
> > Committed r102696: <http://trac.webkit.org/changeset/102696>
> 
> This patch broke (at least) inspector's network panel timeline.
> Should we revert it or there is a quick fix?

What do you mean by broken?

If you're looking at Chrome running with ToT WebKit, then that's expected. The meaning of some of the fields changed and we need to update Chrome to match. I have the patch ready, but am waiting for the WebKit roll before I apply it.

[Vsevolod Vlasov]

(In reply to comment #30)
> (In reply to comment #29)
> > (In reply to comment #27)
> > > (From update of attachment 119047 [details] [details] [details])
> > > Clearing flags on attachment: 119047
> > > 
> > > Committed r102696: <http://trac.webkit.org/changeset/102696>
> > 
> > This patch broke (at least) inspector's network panel timeline.
> > Should we revert it or there is a quick fix?
> 
> What do you mean by broken?
> 
> If you're looking at Chrome running with ToT WebKit, then that's expected. The meaning of some of the fields changed and we need to update Chrome to match. I have the patch ready, but am waiting for the WebKit roll before I apply it.
Yes, I meant Chromium with ToT WebKit. Could you please let me know once you land your patch in chromium, I'll check that I don't see this problem anymore.

[James Simonsen]

(In reply to comment #31)
> Yes, I meant Chromium with ToT WebKit. Could you please let me know once you land your patch in chromium, I'll check that I don't see this problem anymore.

Will do. And sorry about the breakage. I had hoped it wouldn't be broken for so long. I wanted to land them as close together as possible, but the WebKit roll is over a day behind. I'm trying to help out with that now.

[Pavel Feldman]

That's not the way we operate though. We do not leave the product in the inconsistent state since we may end up with the broken Dev channel / Canary builds. What you should do is coordinated landing:

1) roll back this change upstream
2) roll Chromium to ToT
3) land the upstream change
4) Roll the DEPs as a part of the change downstream

Please follow this plan unless the downstream change has landed (I don't believe it has).

[Vsevolod Vlasov]

Reverted: Committed r102908: <http://trac.webkit.org/changeset/102908>

Also, please make sure you have ChangeLog for LayoutTests part as well next time you land it. (prepare-ChangeLog should generate all the ChangeLogs needed).

[James Simonsen]

(In reply to comment #33)
> That's not the way we operate though. We do not leave the product in the inconsistent state since we may end up with the broken Dev channel / Canary builds. What you should do is coordinated landing:
> 
> 1) roll back this change upstream
> 2) roll Chromium to ToT
> 3) land the upstream change
> 4) Roll the DEPs as a part of the change downstream
> 
> Please follow this plan unless the downstream change has landed (I don't believe it has).

That was the plan, but I can't just roll DEPS downstream. WebKit rolls have to be gardened. If I'm lucky, it rolls once a day PST. I'm going to try this again, but if I'm not around for the WebKit roll, can you please check the commit bit on http://codereview.chromium.org/7602023/? You were already a reviewer on it.

[Pavel Feldman]

> That was the plan, but I can't just roll DEPS downstream. WebKit rolls have to be gardened. If I'm lucky, it rolls once a day PST. I'm going to try this again, but if I'm not around for the WebKit roll, can you please check the commit bit on http://codereview.chromium.org/7602023/? You were already a reviewer on it.

Rolling + landing is risky. Please get in touch with the sheriff, explain him your intent. Ask him to prepare the tree for you and land your change right after the roll. Then ask him to land your change downstream together with the DEPs roll.

[James Simonsen]

Committed r102961: <http://trac.webkit.org/changeset/102961>

[Vsevolod Vlasov]

(In reply to comment #37)
> Committed r102961: <http://trac.webkit.org/changeset/102961>

This change still breaks inspector on chromium.
All resources with 304 status code have receiving time set to 15000 days.
I filed https://bugs.webkit.org/show_bug.cgi?id=76176 and added some details and proposed fix there.

simonjam@, could you please have another look on that?