1211168 - Resource timing and timings in network panel of developer tools is inaccurate

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[sajal]

Attachment: ff-timing.png

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/45.0.2454.101 Safari/537.36

Steps to reproduce:

Visit http://imgparent.nodelay.mock.turbobytes.com/foo

It loads http://<random>.imagetest.100msdelay.mock.turbobytes.com:8100/static/rum/image-15kb.jpg in an image tag.

1. dns server of <random>.imagetest.100msdelay.mock.turbobytes.com always injects 100ms latency (it sleeps for 100ms before responding)
2. port 8100 on the webserver injects 100ms delay using tc

The page also prints on screen the values exposed by resource timing.

My useragent: "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:42.0) Gecko/20100101 Firefox/42.0" . But its not limited to my OS or version.


Actual results:

I often see either connect or DNS to be 0 (which is not possible because its a random subdomain so has to be fresh connection and dns -- verified by looking at the wire).

Sometimes connect is ~50% of what i see in wireshark.

In attached screenshot the developer tools says DNS is 0 and connect is what i observed DNS + connect to be.


Expected results:

domainLookupEnd - domainLookupStart should always be > 100ms
connectEnd - connectStart  should always be > 100ms

All the timing info should match whats observed on the wire (using tcpdump/wireshark)

Comment 1

[sajal]

Attachment: domainLookupStart-fix.diff

This patch makes sure that domainLookupStart is only updated if it is null. Without this patch I would occasionally(maybe 1 out of 10 times) see same value for domainLookupStart and domainLookupEnd, with this in place I always see correct timing information in Resource Timing API.

Comment 2

[sajal]

Attachment: rumtestffpcap.py

Comment 3

[sajal]

Attachment: runff.sh

Run scripted tests against firefox.
1. save rumtestffpcap.py and runff.sh in same directory
2. Launch firefox with -marionette.
$ /path/to/firefox -marionette
3. run runff.sh
$ ./runff.sh

Observe timing data exposed by resource timing as well as from analyzing pcap

Comment 4

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

Hi Sajal,

Thanks for the thorough investigation and patch.
While the patch does fix half the problem, I want to check first that we're not merely hiding the problem.
Judging by these results, that would mean nsHttpTransaction::OnTransportStatus gets called multiple times with status == NS_NET_STATUS_RESOLVING_HOST - once just before NS_NET_STATUS_RESOLVED_HOST.

The connectStart/End issue seems to be fixed by setting network.http.speculative-parallel-limit to 0, so indeed it is related to that.

Patrick, what do you think about the RESOLVING_HOST status showing up more than once. Is this something we should fix, or can we simply take this patch?

Comment 5

[sajal]

Additional details from looking at the logs.

http://pastie.org/10463354

Grepping the status message from nsHttpTransaction::OnSocketStatus for a single instance of nsHttpTransaction. Now im not exactly sure whats going on, but status=804b0003 appears to be NS_NET_STATUS_RESOLVING_HOST .

status=804b0003 (NS_NET_STATUS_RESOLVING_HOST) is repeated (2015-10-06 08:06:11.870105 UTC and 2015-10-06 08:06:12.187878 UTC).

status=804b000b (NS_NET_STATUS_RESOLVED_HOST) is repeated (2015-10-06 08:06:11.937342 UTC and 2015-10-06 08:06:12.188110 UTC)

The first NS_NET_STATUS_RESOLVING_HOST and second NS_NET_STATUS_RESOLVED_HOST appear to be real one. : 2015-10-06 08:06:12.188110 -  2015-10-06 08:06:11.870105) 318ms is the actual DNS time as observed from packet capture.

Comment 6

[Patrick McManus [:mcmanus]]

(In reply to Valentin Gosu [:valentin] from comment #4)
> 
> Patrick, what do you think about the RESOLVING_HOST status showing up more
> than once. Is this something we should fix, or can we simply take this patch?

I guess either way is ok.. in truth it is happening more than once, so best to just make the timings paper it over rather than suppressing the event.

Comment 7

[Patrick McManus [:mcmanus]]

Comment on attachment 8669412 [details] [diff] [review]
domainLookupStart-fix.diff

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

thanks!

Comment 8

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/fd660e3112d6f2f1d9d121450eaff6ed1ac31a76
Bug 1211168 - Fix resource timing domainLookupStart by setting the timestamp only once. r=mcmanus

Comment 9

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/fd660e3112d6

Comment 10

[sajal]

re-opening because the patch sort of mitigates half the problem, connect timing is still incorrect.

Comment 11

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

(In reply to sajal from comment #10)
> re-opening because the patch sort of mitigates half the problem, connect
> timing is still incorrect.

I filed bug 1213699 to fix the connnectStart/End timings.
Closing this bug as the DNS timings are fixed.

Comment 12

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

Closing in favor of bug 1213699.