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]
:
: 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 | Splinter 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 | Splinter Review

Description User image 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 User image 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 User image Patrick McManus [:mcmanus] 2012-06-21 10:19:25 PDT
Created attachment 635361 [details] [diff] [review]
patch 0
Comment 3 User image 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 User image 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 User image 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 User image 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 User image 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 User image 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 User image Patrick McManus [:mcmanus] 2012-06-26 07:45:58 PDT
steve, honza: opinions on backporting?
Comment 10 User image Patrick McManus [:mcmanus] 2012-06-26 08:14:34 PDT
https://hg.mozilla.org/integration/mozilla-inbound/rev/65536f28b65e
Comment 11 User image 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 User image 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 User image Ed Morley [:emorley] 2012-06-27 03:37:06 PDT
https://hg.mozilla.org/mozilla-central/rev/65536f28b65e
Comment 14 User image 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 User image 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 User image 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.