919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart <0

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[gao_yanting]

Attachment: requestTime NegativeValue.jpg

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101 Firefox/24.0 (Beta/Release)
Build ID: 20130910160258

Steps to reproduce:

1. Open FF and open the dev tools (F12)
2. Paste following code in the dev window: 
requestTime = performance.timing.responseStart - performance.timing.requestStart;
alert("request: " + requestTime.toString());
3.Render one website, eg: https://www.google.com/ 
4.Select above code and run, to make request value pop up. Screenshot attached.
5.Usually you should try several times to get result requestTime <0.
  It is easy to reproduce.

Comment 1

[sjw]

You are using Firebug in your screenshot. Does this bug affect the Firefox console, too? Please try to reproduce in safe-mode.

Comment 2

[Adam Roben]

We are seeing this on navigations on github.com (I'm a GitHub engineer). We're seeing it across many Firefox versions (at least v16-v27) and OSes (Mac, Windows, Linux). Here's a sample performance.timing dump:

            0 redirectEnd
            0 unloadEventStart
            0 unloadEventEnd
            0 redirectStart
1392331282549 navigationStart
1392331282556 connectEnd
1392331282556 domainLookupStart
1392331282556 domainLookupEnd
1392331282556 connectStart
1392331282556 fetchStart
1392331282770 responseStart
1392331283446 requestStart
1392331283676 responseEnd
1392331283686 domLoading
1392331284345 domInteractive
1392331284465 domContentLoadedEventStart
1392331284468 domContentLoadedEventEnd
1392331286649 domComplete
1392331286649 loadEventStart
1392331286654 loadEventEnd

Comment 3

[Kanchan Kumari QA]

Hello Reporter, thank for reporting this issue. I tried duplicating this problem on the latest released version of Firefox (43.0.4) by executing your Javascript several times (25-30 times) on different websites but never saw any negative value. I tried on Windows 7 64 bit machine using:

Name 	Firefox
Version 	43.0.4
Build ID 	20160105164030
Update Channel 	release
User Agent 	Mozilla/5.0 (Windows NT 6.1; WOW64; rv:43.0) Gecko/20100101 Firefox/43.0

If you have not upgraded so far, may I request you to try again on the latest FF version and let us know if you still see the problem.

Comment 4

[Kanchan Kumari QA]

Resolved-Incomplete due to time since last communication/update by reporter.
Please feel free to reopen if the error occurs in a current Firefox version.

Comment 5

[Boris Zbarsky [:bzbarsky]]

Reopening based on report of this happening on some Google sites as well.  Note that response start as defined in the spec can in fact chronologically precede request start in some situations (e.g. http/2 push),  but the spec also says to lie and clamp response start to be no earlier than request start and it's possible we're not doing that clamping...

Valentin, could you take a look please?

Comment 6

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

Attachment: Bug 919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0

Review commit: https://reviewboard.mozilla.org/r/97648/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/97648/

Comment 7

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

This also fixes the following bug with: gzip_xml.py

0:35.80 LOG: Thread-14 wptserve WARNING Traceback (most recent call last):
  File "mozilla-central/testing/web-platform/tests/tools/wptserve/wptserve/handlers.py", line 246, in __call__
    rv = self.func(request, response)
  File "mozilla-central/testing/web-platform/tests/resource-timing/resources/gzip_xml.py", line 5, in main
    f = open('resource-timing/resources/resource_timing_test0.xml', 'r')
IOError: [Errno 2] No such file or directory: 'resource-timing/resources/resource_timing_test0.xml'

Comment 8

[Andrea Marchesini [:baku]]

Comment on attachment 8817313 [details]
Bug 919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0

https://reviewboard.mozilla.org/r/97648/#review97972

Looks good to me. I didn't review the WPT part.

Comment 9

[James Graham [:jgraham]]

Comment on attachment 8817313 [details]
Bug 919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0

https://reviewboard.mozilla.org/r/97648/#review97992

::: testing/web-platform/tests/resource-timing/resources/gzip_xml.py:7
(Diff revision 1)
>  from cStringIO import StringIO
> +import os
>  
>  def main(request, response):
> -    f = open('resource-timing/resources/resource_timing_test0.xml', 'r')
> +    dir_path = os.path.dirname(os.path.realpath(__file__))
> +    f = open(dir_path+'/resource_timing_test0.xml', 'r')

This should use `os.path.join` rather than assuming that the separator is a `/`

Comment 10

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/b3b5af78a162b11a9a838087c0f6ad3567eeb55e
Bug 919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0 r=baku,jgraham

Comment 11

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/a77180ae4e06 for Win7 https://treeherder.mozilla.org/logviewer.html#?job_id=40409324&repo=mozilla-inbound and Linux32 https://treeherder.mozilla.org/logviewer.html#?job_id=40397659&repo=mozilla-inbound

Comment 12

[Andrew Overholt [:overholt]]

Valentin, are you able to pick this back up again?

Comment 13

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

Yes, I'll try to fix and land the patch in the next few days.

Comment 14

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/e776663ecbb4df20c2ed612cbaf5d5e2808ab6bb
Bug 919391 - Fix gzip_xml.py not finding resource_timing_test0.xml r=jgraham

Comment 15

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/c3a4bae5fc8db328f9f8559a65b28c235743bc10
Bug 919391 - (fix) Use os.path.join instead a=testonly

Comment 16

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

Things were still failing, so both patches backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/fe960e54cc30

https://treeherder.mozilla.org/logviewer.html#?job_id=77692308&repo=mozilla-inbound

Comment 17

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

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

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/4a471c993ab6
Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0 r=baku

Comment 19

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/4a471c993ab69ec865e40ab9a94342761d9ef0a5
Bug 919391 - Incorrect Navigation Timing API: performance.timing.responseStart - performance.timing.requestStart < 0 r=baku

Comment 20

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

https://hg.mozilla.org/mozilla-central/rev/4a471c993ab6

Comment 21

[Firefox Bug Husbandry Bot]

Removing leave-open keyword from resolved bugs, per :sylvestre.