Incorrect Navigation Timing API responseEnd milestone

RESOLVED FIXED in Firefox 14

Status

()

Core
Networking: HTTP
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: Steve Jiang, Assigned: mcmanus)

Tracking

Trunk
mozilla16
x86
Mac OS X
Points:
---

Firefox Tracking Flags

(firefox13 affected, firefox14 fixed, firefox15 verified, firefox16 fixed)

Details

(Whiteboard: [spdy])

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

5 years ago
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:15.0) Gecko/20120613 Firefox/15.0a2
Build ID: 20120613042011

Steps to reproduce:

Navigate to a SPDY-capable site, e.g. https://www.google.com/ or https://twitter.com/

Open web console and check the values in performance.timing, specifically responseEnd:

performance.timing.responseEnd - performance.timing.responseStart


Actual results:

responseEnd is earlier than responseStart for the first SPDY request of a connection

Tested in 13.0 release, 15.0a2 (2012-06-13), and 16.0a1 (2012-06-13)


Expected results:

responseEnd should properly reflect the time the browser receives the last byte of the document.
(Assignee)

Updated

5 years ago
Component: Networking → Networking: HTTP
QA Contact: networking → networking.http
Whiteboard: [spdy]
(Assignee)

Comment 1

5 years ago
I think I see what's going on here.. 

responseEnd is only recorded in HttpTransaction when a content-length is reached or when the end of a chunked-encoding is found.

it does not seem to be recorded on BASE_STREAM_CLOSED.. That would seem to be a bug in all versions of plain HTTP. 

Spdy doesn't use HTTP chunked encodings, it has its own (similar) framing layer.. it uses that to signal the http layer that a transaction is done through BASE_STREAM_CLOSED. So This is a lot more visible in spdy.
Assignee: nobody → mcmanus
(Assignee)

Updated

5 years ago
Summary: Incorrect Navigation Timing API responseEnd milestone on SPDY requests → Incorrect Navigation Timing API responseEnd milestone
(Assignee)

Comment 2

5 years ago
Created attachment 635361 [details] [diff] [review]
patch 0
Attachment #635361 - Flags: review?(honzab.moz)
(Reporter)

Comment 3

5 years ago
I'm not familiar with the implementation but I can't reproduce the bug with an HTTP response that is Connection: close without Content-Length or chunked encoding.
(Assignee)

Comment 4

5 years ago
(In reply to Steve Jiang from comment #3)
> I'm not familiar with the implementation but I can't reproduce the bug with
> an HTTP response that is Connection: close without Content-Length or chunked
> encoding.

interesting..

can you try your original test case with the patch (or there are try builds being made at https://tbpl.mozilla.org/?tree=Try&rev=8bca4cfb154a) 

I did repro and verify according to how I understood your bug report.
(Reporter)

Comment 5

5 years ago
(In reply to Patrick McManus [:mcmanus] from comment #4)
> can you try your original test case with the patch (or there are try builds
> being made at https://tbpl.mozilla.org/?tree=Try&rev=8bca4cfb154a) 

Thanks Patrick, I did verify with the try build that the bug when using spdy is fixed.
Comment on attachment 635361 [details] [diff] [review]
patch 0

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

r=honza with comments addressed.

http://www.w3.org/TR/navigation-timing/#dom-performancetiming-responseend

::: netwerk/protocol/http/nsHttpTransaction.cpp
@@ +762,5 @@
> +        // HTTP delimiter such as chunked-encodings or content-length. However,
> +        // EOF is a successful termination as well and if that happened this is
> +        // the place to record it.
> +        if (TimingEnabled() && mTimings.responseEnd.IsNull())
> +            mTimings.responseEnd = mozilla::TimeStamp::Now();

This also has to be measured when the connection or the request in any moment fails.  So, do this always in nsHttpTransaction::Close().
Attachment #635361 - Flags: review?(honzab.moz) → review+
(Assignee)

Comment 7

5 years ago
Created attachment 635561 [details] [diff] [review]
patch 1

if we're going to set responseEnd on NS_FAILED, I think we should only do it if responseStart has already been set.. look good?
Attachment #635361 - Attachment is obsolete: true
Attachment #635561 - Flags: review?(honzab.moz)
Comment on attachment 635561 [details] [diff] [review]
patch 1

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

Thanks. r=honzab.
Attachment #635561 - Flags: review?(honzab.moz) → review+
(Assignee)

Comment 9

5 years ago
steve, honza: opinions on backporting?
(Assignee)

Comment 10

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/65536f28b65e
status-firefox13: --- → affected
status-firefox14: --- → affected
status-firefox15: --- → affected
status-firefox16: --- → fixed
Target Milestone: --- → mozilla16
(Reporter)

Comment 11

5 years ago
I'm using the timing api to track site performance including network latency.  It's not a critical bug, but I'd be great to get this backported.

The amount of valid data has dropped by about 20% as more users have upgraded to FF13 with SPDY enabled by default, and it prevents a comparison of SPDY versus straight HTTP.
status-firefox13: affected → ---
status-firefox14: affected → ---
status-firefox15: affected → ---
status-firefox16: fixed → ---
status-firefox13: --- → affected
status-firefox14: --- → affected
status-firefox15: --- → affected
status-firefox16: --- → fixed
(Assignee)

Comment 12

5 years ago
(In reply to Steve Jiang from comment #11)
 and it prevents a comparison
> of SPDY versus straight HTTP.

add subresource timing and that would be an interesting comparison :)
https://hg.mozilla.org/mozilla-central/rev/65536f28b65e
Status: UNCONFIRMED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
(Assignee)

Comment 14

5 years ago
Comment on attachment 635561 [details] [diff] [review]
patch 1

[Approval Request Comment]
Bug caused by (feature/regressing bug #): original nav timing bug
User impact if declined: nav timing spec does not work on some pages, more prominently with spdy
Testing completed (on m-c, etc.): on m-c
Risk to taking this patch (and alternatives if risky): about as low risk as you can get
String or UUID changes made by this patch: none

steve advocates for a backport in comment 11 with some notes on impact
Attachment #635561 - Flags: approval-mozilla-beta?
Attachment #635561 - Flags: approval-mozilla-aurora?
Comment on attachment 635561 [details] [diff] [review]
patch 1

Approving for landing since it's extremely low risk and helps with a functionality issue that wouldn't be great to have around for 6 weeks.  Please land this to mozilla-beta today if possible or before noon PT tomorrow (Tuesday) so it can be in the next beta we build later tomorrow.
Attachment #635561 - Flags: approval-mozilla-beta?
Attachment #635561 - Flags: approval-mozilla-beta+
Attachment #635561 - Flags: approval-mozilla-aurora?
Attachment #635561 - Flags: approval-mozilla-aurora+
(Assignee)

Comment 16

5 years ago
https://hg.mozilla.org/releases/mozilla-aurora/rev/7be3b66ed6bd
https://hg.mozilla.org/releases/mozilla-beta/rev/1488342397e3
status-firefox14: affected → fixed
status-firefox15: affected → fixed

Comment 17

5 years ago
Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:15.0) Gecko/20100101 Firefox/15.0

Verified this several times while connecting to google sites and to twitter. All the responseEnd values were larger than their corresponding responseStarts.
status-firefox15: fixed → verified
You need to log in before you can comment on or make changes to this bug.