Last Comment Bug 764648 - Incorrect Navigation Timing API responseEnd milestone
: Incorrect Navigation Timing API responseEnd milestone
Status: RESOLVED FIXED
[spdy]
:
Product: Core
Classification: Components
Component: Networking: HTTP (show other bugs)
: Trunk
: x86 Mac OS X
: -- normal (vote)
: mozilla16
Assigned To: Patrick McManus [:mcmanus]
:
Mentors:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-06-13 16:38 PDT by Steve Jiang
Modified: 2012-07-27 07:51 PDT (History)
4 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
affected
fixed
verified
fixed


Attachments
patch 0 (1.31 KB, patch)
2012-06-21 10:19 PDT, Patrick McManus [:mcmanus]
honzab.moz: review+
Details | Diff | Review
patch 1 (1.26 KB, patch)
2012-06-21 18:25 PDT, Patrick McManus [:mcmanus]
honzab.moz: review+
lukasblakk+bugs: approval‑mozilla‑aurora+
lukasblakk+bugs: approval‑mozilla‑beta+
Details | Diff | Review

Description Steve Jiang 2012-06-13 16:38:13 PDT
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] 2012-06-21 09:16:40 PDT
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] 2012-06-21 10:19:25 PDT
Created attachment 635361 [details] [diff] [review]
patch 0
Comment 3 Steve Jiang 2012-06-21 10:21:38 PDT
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] 2012-06-21 10:34:05 PDT
(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 2012-06-21 11:39:20 PDT
(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) 2012-06-21 16:04:05 PDT
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] 2012-06-21 18:25:03 PDT
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?
Comment 8 Honza Bambas (:mayhemer) 2012-06-26 07:29:23 PDT
Comment on attachment 635561 [details] [diff] [review]
patch 1

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

Thanks. r=honzab.
Comment 9 Patrick McManus [:mcmanus] 2012-06-26 07:45:58 PDT
steve, honza: opinions on backporting?
Comment 10 Patrick McManus [:mcmanus] 2012-06-26 08:14:34 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/65536f28b65e
Comment 11 Steve Jiang 2012-06-26 14:54:37 PDT
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] 2012-06-26 17:52:30 PDT
(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] 2012-06-27 03:37:06 PDT
https://hg.mozilla.org/mozilla-central/rev/65536f28b65e
Comment 14 Patrick McManus [:mcmanus] 2012-06-28 07:40:39 PDT
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 2012-07-02 14:25:44 PDT
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 17 Ioana (away) 2012-07-27 07:51:19 PDT
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.

Note You need to log in before you can comment on or make changes to this bug.