764648 - Incorrect Navigation Timing API responseEnd milestone

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[Steve Jiang]

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.

Comment 1

[Patrick McManus [:mcmanus]]

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.

Comment 2

[Patrick McManus [:mcmanus]]

Attachment: patch 0

Comment 3

[Steve Jiang]

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.

Comment 4

[Patrick McManus [:mcmanus]]

(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.

Comment 5

[Steve Jiang]

(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 6

[Honza Bambas (:mayhemer)]

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().

Comment 7

[Patrick McManus [:mcmanus]]

Attachment: 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?

Comment 8

[Honza Bambas (:mayhemer)]

Comment on attachment 635561 [details] [diff] [review]
patch 1

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

Thanks. r=honzab.

Comment 9

[Patrick McManus [:mcmanus]]

steve, honza: opinions on backporting?

Comment 10

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/65536f28b65e

Comment 11

[Steve Jiang]

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.

Comment 12

[Patrick McManus [:mcmanus]]

(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 :)

Comment 13

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/65536f28b65e

Comment 14

[Patrick McManus [:mcmanus]]

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

Comment 15

[Lukas Blakk [:lsblakk] use ?needinfo]

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.

Comment 16

[Patrick McManus [:mcmanus]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/7be3b66ed6bd
https://hg.mozilla.org/releases/mozilla-beta/rev/1488342397e3

Comment 17

[Ioana (away)]

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.