1123920 - Resource Timing domainLookupEnd and requestStart out-of-order

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Steve Souders]

Attachment: ff-res-timing.png

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.9; rv:35.0) Gecko/20100101 Firefox/35.0
Build ID: 20150108202552

Steps to reproduce:

Loaded a website and investigated performance.getEntries()


Actual results:

Several entries (resources) have requestStart less than domainLookupEnd. I've attached a screenshot showing the output in Developer Tools. Here are the resource entry's properties sorted:
0: redirectEnd, redirectStart, secureConnectionStart
1545.600197: connectEnd, connectStart, fetchStart, requestStart, startTime
1545.682271: domainLookupStart
1648.527292: domainLookupEnd
1648.580909: responseStart
1872.783224: responseEnd


Expected results:

requestStart MUST be greater than domainLookupEnd according to the spec (see http://www.w3.org/TR/resource-timing/#processing-model).

Comment 1

[:Gijs (he/him)]

Valentin, do you know what's going on here?

(I can trivially reproduce on 36 beta, at least, by inspecting this page's getEntries() - the main CSS file shows the same issue)

Comment 2

[Valentin Gosu [:valentin] (he/him)]

This is a bug in our implementation: bug 1079837 comment 457
Thanks for filing it, Steve.

Comment 3

[Valentin Gosu [:valentin] (he/him)]

Attachment: requestStart timestamp is before connectEnd

This patch does not fix the issue in this bug's description, but it does take care of the one in bug 1079837. The problem was with reused connections, for which it seems that OnTransportStatus(NS_NET_STATUS_CONNECTED_TO) is called after ReadRequestSegment, and messes up the expected order of the timestamps. Does this approach seem acceptable, or is there a way to change the order those methods are called?

A patch for the other issue is also incoming.

Comment 4

[Valentin Gosu [:valentin] (he/him)]

Attachment: Resource Timing domainLookupEnd and requestStart out-of-order

It seems that sometimes OnLookupComplete is called after the requestStart timestamp (first write to socket) - maybe because the dnsEntry expires while the socket is still connecte, or maybe for some other reason. In any case, using the dnsPrefetch's timestamps isn't appropriate.

Comment 5

[Patrick McManus [:mcmanus]]

Comment on attachment 8567430 [details] [diff] [review]
requestStart timestamp is before connectEnd

Review of attachment 8567430 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/protocol/http/nsHttpTransaction.cpp
@@ +516,5 @@
> +        // If the connection is reused, we may already have a usable socket,
> +        // and the requestStart may already be set.
> +        // These attributes need to be smaller or equal to requestStart.
> +        mozilla::TimeStamp timestamp = (mConnection && mConnection->IsReused())
> +             ? Timings().requestStart : TimeStamp::Now();

this doesn't feel right.. why is the check IsReused() rather than  some variation of !requestStart.IsNull()

maybe:
timestamp = requestStart.IsNull() ? TimeStamp::Now : requestStart;

Comment 6

[Patrick McManus [:mcmanus]]

(In reply to Valentin Gosu [:valentin] from comment #4)
> Created attachment 8567765 [details] [diff] [review]
> Resource Timing domainLookupEnd and requestStart out-of-order
> 
> It seems that sometimes OnLookupComplete is called after the requestStart
> timestamp (first write to socket) - maybe because the dnsEntry expires while
> the socket is still connecte, or maybe for some other reason.

I think you're right.. I think the prefetch really does a DNS query (and thus is 'valid') because of a dns cache expiration but the socket code actually never uses that lookup because a persistent connection is used instead.

> In any case,
> using the dnsPrefetch's timestamps isn't appropriate.

this is a little less clear (taking them if they are less than the other values might make sense) it is conservative

Comment 7

[Valentin Gosu [:valentin] (he/him)]

Attachment: requestStart timestamp is before connectEnd when using persistent connections

Comment 8

[Valentin Gosu [:valentin] (he/him)]

Attachment: ConnectStart and ConnectEnd should call DomainLookupEndHighRes if null

Comment 9

[Valentin Gosu [:valentin] (he/him)]

Attachment: domainLookupEnd and requestStart out-of-order when using a persistent connection

Comment 10

[(no longer active)]

Comment on attachment 8568892 [details] [diff] [review]
ConnectStart and ConnectEnd should call DomainLookupEndHighRes if null

Review of attachment 8568892 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/base/nsPerformance.cpp
@@ +276,5 @@
>      return mZeroTime;
>    }
> +  return (!mConnectStart.IsNull())
> +          ? TimeStampToDOMHighRes(mConnectStart)
> +          : DomainLookupEndHighRes();

Please reverse the conditional, like:

  return mConnectStart.IsNull() ?
         // null case :
         // non-null case;

@@ +293,5 @@
>      return mZeroTime;
>    }
> +  return (!mConnectEnd.IsNull())
> +          ? TimeStampToDOMHighRes(mConnectEnd)
> +          : DomainLookupEndHighRes();

Ditto.

Comment 11

[Valentin Gosu [:valentin] (he/him)]

Try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5ac031a44452

Inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b1f219eb3e57
https://hg.mozilla.org/integration/mozilla-inbound/rev/8a14f387e393
https://hg.mozilla.org/integration/mozilla-inbound/rev/f1fc4df52d3e

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/b1f219eb3e57
https://hg.mozilla.org/mozilla-central/rev/8a14f387e393
https://hg.mozilla.org/mozilla-central/rev/f1fc4df52d3e

Comment 13

[Ryan VanderMeulen [:RyanVM]]

How far back can we safely backport this?

Comment 14

[Ryan VanderMeulen [:RyanVM]]

37 and 38 are both long-lived branches, so I'd really like to get it on both if possible.

Comment 15

[Valentin Gosu [:valentin] (he/him)]

Attachment: ConnectStart and ConnectEnd should call DomainLookupEndHighRes if null

The patch pushed to m-c. r+'ed by ehsan in comment 10

Comment 16

[Valentin Gosu [:valentin] (he/him)]

Aurora:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e637a6c86a46
Beta:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=40f15f3d3c11

Need to figure out the failures, will nominate after :)

Comment 18

[Valentin Gosu [:valentin] (he/him)]

(In reply to Valentin Gosu [:valentin] from comment #16)
> Aurora:
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=e637a6c86a46
> Beta:
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=40f15f3d3c11
> 

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6fef3331b56d

Ryan, I have looked into the failures. The oranges don't seem to be related to this patch.
My main concern is the failure in the Crashtest - it fails in gfx in something dealing with timestamps. Have you seen this before? I'm a bit puzzled about how I'd fix this - or what patches I'd also need to uplift to make this work.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

None of those matter for the release branches. Keep in mind that some of those test suites normally only run on trunk :)

Comment 20

[Valentin Gosu [:valentin] (he/him)]

Attachment: [Beta] requestStart timestamp is before connectEnd when using persistent connections

Comment 21

[Valentin Gosu [:valentin] (he/him)]

Comment on attachment 8568890 [details] [diff] [review]
requestStart timestamp is before connectEnd when using persistent connections

Approval Request Comment

Patch series for aurora: attachment 8568886 [details] [diff] [review], attachment 8568890 [details] [diff] [review], attachment 8569939 [details] [diff] [review], attachment 8568902 [details] [diff] [review]

Patch series for beta: attachment 8576678 [details] [diff] [review], attachment 8576679 [details] [diff] [review], attachment 8569939 [details] [diff] [review], attachment 8568902 [details] [diff] [review]

[Feature/regressing bug #]:
Issue has been present since the initial implementation of timing interface for channels.
[User impact if declined]:
Incorrect ResourceTiming and PerformanceTiming values for resources that are served over a persistent connection.
These patches depend on the patch in bug 1132572 which fixes a data race.
This also reenables several tests for resource timing.
[Describe test coverage new/current, TreeHerder]:
Has been on nightly for a few weeks. Treeherder try pushes.
[Risks and why]:
The risks are low. The patches aren't overly complex.
Possible regression described in bug 1139831 (minor, compared to improvements gained by uplifting this bug)
[String/UUID change made/needed]:
None.

Comment 22

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8568890 [details] [diff] [review]
requestStart timestamp is before connectEnd when using persistent connections

After speaking with Valentin, this change isn't critical enough to take in Firefox 37. As Ryan said, b2g37 will be a long lived branch so it may make sense to take this change there. We should take this change in 38, which is the next ESR (long lived) branch. I'm going to deny uplift to Beta but nom for b2g37 (see comment 21) and approve for Aurora.

Comment 23

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8568890 [details] [diff] [review]
requestStart timestamp is before connectEnd when using persistent connections

Actually, it's the other three patches on this bug that are required for b2g37.

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/2e1a4ce4eed8
https://hg.mozilla.org/releases/mozilla-aurora/rev/64032a38ad65
https://hg.mozilla.org/releases/mozilla-aurora/rev/12ef28874ba5

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/69c9925f764c
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/7eb881a04d1e
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/7d83cd2cb103