1213699 - ConnectStart/End timings are incorrect

Status: NEW

(Core :: Networking, defect, P3)

Description

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

+++ This bug was initially created as a clone of Bug #1211168 +++

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.

Expected results:

connectEnd - connectStart  should always be > 100ms

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

----------------

This issue seems to be fixed by setting network.http.speculative-parallel-limit to 0. However, we probably want a more general fix. See bug 1211168

Comment 1

[sajal]

Heres what I think is happening.

1. nsHttpChannel::Connect calls SpeculativeConnect() before checking with cache. it starts the process of making half open connection.
2. Cache miss ( because my test http://imgparent.nodelay.mock.turbobytes.com/ is loading a random url)
3. A nsHttpTransaction is called and the connection from #1 is injected into it. Because the connection was initiated earlier in step #1, this nsHttpTransaction does not get connection related events.

There is probably very little gap between step #1 and #3.

I propose nsHalfOpenSocket should store the timing data, and when its being injected to nsHttpTransaction , and its the first request on the socket - the dns/connect timing should be added via nsHttpTransaction::SetConnectStart , nsHttpTransaction::SetConnectEnd, etc.

Comment 3

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 4

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258