Closed Bug 1072478 Opened 10 years ago Closed 10 years ago

loading never stops due to slow SPDY push

Categories

(Core :: Networking: HTTP, defect)

Product:
Core
Component:
Networking: HTTP
Version:
32 Branch
Platform:
x86_64
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla37

People

(Reporter: amwebdk, Assigned: mcmanus)

References

Details

(Whiteboard: [spdy])

Attachments

(4 files, 5 obsolete files)

server.js
1.83 KB, text/javascript
Details
h2 push loses fin bit race condition 1/2
2.21 KB, patch
mcmanus
: review+
Details | Diff | Splinter Review
INTERDIFF
25.03 KB, patch
Details | Diff | Splinter Review
h2 push hit not subject to max_concurrent 2/2
56.88 KB, patch
mcmanus
: review+
Details | Diff | Splinter Review
Attached file server.js —
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/37.0.2062.122 Safari/537.36 Steps to reproduce: Consider this SPDY enabled website: <!DOCTYPE html> <link rel="stylesheet" href="/slow.css"> where slow.css is send using SPDY PUSH, but the content is delayed. (When running a localhost just delaying it 10ms is enough to cause the issue) Now go to the site an observe that the site never stops loading and the layout is as if /slow.css isn't yet loaded. The test server (in node.js using node-spdy) is attached. I think this is caused by an race condition between the PUSH stream and the parsing of the <link ...> tag. Because if I remove the <link> tag the page loading stops quite quickly. The test pass in Chrome. Actual results: 1) Firefox send a request for the main HTML page. 2) It then acknowledge the push stream for /slow.css. 3) The slow.css file content is send, but not received by firefox. For instance it dosn't show up in the inspector. The test server output is: test server: https://localhost:8000 - Request for / send - push content send Expected results: 1) Firefox send a request for the main HTML page. 2) It then acknowledge the push stream for /slow.css. 3) The slow.css file content is send, firefox rerenders the page and stops showing the loading animation. The test server output should not change: test server: https://localhost:8000 - Request for / send - push content send
Whiteboard: [spdy]
Hardware: x86 → x86_64
Component: Networking → Networking: HTTP
Summary: loading never stops dude to slow SPDY push → loading never stops due to slow SPDY push
this is spdy/3.1.. I can confirm the str
Status: UNCONFIRMED → NEW
Ever confirmed: true
Assignee: nobody → mcmanus
Status: NEW → ASSIGNED
primarily this is triggered by an invalid server side config. (btw - thanks for including the server code!) You server sends a settings for MAX_CONCURRENT of 0. Firefox requests / 0x1 before receiving that settings.. so it sends it based on the default MAX_CONCURRENT of 100. But that's just a race condition - we certainly may never send the request for / either. by the time firefox needs to generate the request for slow.css it has processed the MAX_CONCURRENT of 0 and queues the request, waiting for the server to recover. (we treat this as a server request to slow down for a minute). I think that's a firefox bug too in the sense that the pushed stream has been accepted and will not count against the MAX_CONCURRENT number.. so queueing is premature. I will pursue this. This is the node-spdy code that sets it to 0 https://github.com/indutny/node-spdy/blob/808270dac4804aaef328062cc084745a8169da83/lib/spdy/connection.js#L30 you can workaround it and have your test work fine by adding maxStreams : 100 to your options in your server code.
I must admit that I haven't checked the actual network traffic, so it possible that MAX_CONCURRENT is 0. But from what I can see (using console.log(state.maxStreams)), the maxStreams was set to 100 (spdy version 1.28.1). Also explicitly setting maxStreams : 100, makes no difference in the test.
(In reply to Andreas Madsen from comment #3) > > console.log(state.maxStreams)), the maxStreams was set to 100 (spdy version > 1.28.1). interestingly, 1.28.1 sends maxStreams 100.. 1.29.0 sent 0. That's probably a node-spdy bug.
Indutny (author of node-spdy) have confirmed there is a bug in node-spdy 1.29.0: https://github.com/indutny/node-spdy/issues/180 . But since the testcase fails with node-spdy 1.28.1 too, this doesn't solve the entire problem.
ack.. I had to update the timeout to 1000 to see it locally
Attachment #8506397 - Flags: review?(hurley)
Attachment #8506398 - Flags: review?(hurley)
the original problem turned out to be much simpler... in the case where the push fin arrives arrives after all the data bytes have been by a synthetic pull (i.e. the css parser in this case - not the push cache) then when the fin does arrive it gets stuck in the pipe between the push and css parser. we've got patches here for that problem as well as the max_concurrent problem. Thanks andrea - can you confirm the fix from the try builds (they'll take a couple hours to complete) https://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/mcmanus@ducksong.com-5f20d62a1740/ https://tbpl.mozilla.org/?tree=Try&rev=5f20d62a1740
Thanks The Mac build appears to be corrupted, but the Windows build works fine. I will consider this bug fixed.
thanks.. I've started a more thorough try run just to make sure nothing bad is going on with the patches and mac. https://tbpl.mozilla.org/?tree=Try&rev=1f06cc0e98ee
Attachment #8506398 - Flags: review?(hurley) → review+
Comment on attachment 8506397 [details] [diff] [review] h2 push hit not subject to max_concurrent 2/2 Review of attachment 8506397 [details] [diff] [review]: ----------------------------------------------------------------- So the two big comments apply equally to spdy and h2, but I didn't feel like duplicating myself :) ::: netwerk/protocol/http/Http2Session.cpp @@ +437,5 @@ > + mReadyForWrite.Push(stream); > + SetWriteCallbacks(); > + > + // Kick off the SYN transmit without waiting for the poll loop > + // This won't work for stream id=1 because there is no segment reader nit: stream id=3 for h2 :) ::: netwerk/protocol/http/Http2Stream.cpp @@ +341,4 @@ > // RegisterStreamID (below) because of the push match. > // Release that semaphore count immediately (instead of waiting for > // cleanup stream) so we can initiate more pull streams. > mSession->MaybeDecrementConcurrent(this); It's not clear to me that this is still necessary. It won't hurt anything, but I'm fairly certain it will always be a no-op (we don't call IncrementConcurrent until after this code has executed). @@ +1100,5 @@ > + } > + } > + > + if (mRequestHeadersDone && !mOpenGenerated) { > + if (!mSession->RoomForMoreConcurrent()) { So I'm not crazy about the stream having to explicitly manage the concurrency situation in the session. I know these two things don't have the greatest separation in the code already, but this seems a bit much. How would you feel about doing something like if (!mSession->TryToActivate(this)) { return NS_OK; } and Http2Session::TryToActivate (or whatever you want to call it) will take care of the RoomForMoreConcurrent ? IncrementConcurrent : QueueStream logic. It doesn't change the logic any, but it leaves a little more separation in terms of managing the concurrency count (and actually separates it entirely, if we remove the call to MaybeDecrementConcurrent noted above). @@ +1105,5 @@ > + LOG3(("Http2Stream::OnReadSegment %p no room for more concurrent " > + "streams %d\n", this)); > + mSession->QueueStream(this); > + return NS_OK; > + } nit: indentation ::: netwerk/protocol/http/SpdyStream3.cpp @@ +1462,5 @@ > + LOG3(("SpdyStream3::OnReadSegment %p no room for more concurrent " > + "streams %d\n", this)); > + mSession->QueueStream(this); > + return NS_OK; > + } nit: indentation ::: netwerk/protocol/http/SpdyStream31.cpp @@ +1480,5 @@ > + LOG3(("SpdyStream31::OnReadSegment %p no room for more concurrent " > + "streams %d\n", this)); > + mSession->QueueStream(this); > + return NS_OK; > + } nit: indentation
Attachment #8506397 - Flags: review?(hurley)
Attachment #8544141 - Flags: review?(hurley)
Attachment #8506397 - Attachment is obsolete: true
Comment on attachment 8544139 [details] [diff] [review] h2 push loses fin bit race condition 1/2 updated for bitrot
Attachment #8544139 - Flags: review+
nick - good suggestions. thanks.
Attachment #8544141 - Flags: review?(hurley) → review+
https://hg.mozilla.org/mozilla-central/rev/047afa953b9c https://hg.mozilla.org/mozilla-central/rev/28fff54451dd
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla37
Depends on: 1119810
Depends on: 1119926
I'm going to backout the pushes in 18
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
from bug 1119926 a good test before relanding: https://www.httpvshttps.com/
Depends on: 1120096
these were backed out of mozilla-central with parent b098bff0d341 (gecko37)
Keywords: leave-open
Attachment #8544139 - Attachment is obsolete: true
Attachment #8549995 - Flags: review?(hurley)
Attachment #8544141 - Attachment is obsolete: true
Comment on attachment 8506398 [details] [diff] [review] h2 push loses fin bit race condition 1/2 ># HG changeset patch ># User Patrick McManus <mcmanus@ducksong.com> ># Date 1413492134 14400 ># Thu Oct 16 16:42:14 2014 -0400 ># Node ID ad5bb05c17fa2416e18008636d14e0bf7c2b8ab7 ># Parent b2162376e0656484eafa8b61418979084786b347 >bug 1072478 - h2 push loses fin bit race condition 1/2 r=hurley > >diff --git a/netwerk/protocol/http/Http2Push.cpp b/netwerk/protocol/http/Http2Push.cpp >--- a/netwerk/protocol/http/Http2Push.cpp >+++ b/netwerk/protocol/http/Http2Push.cpp >@@ -255,23 +255,23 @@ Http2PushTransactionBuffer::WriteSegment > count, countWritten); > if (NS_SUCCEEDED(rv)) { > mBufferedHTTP1Used += *countWritten; > } > else if (rv == NS_BASE_STREAM_CLOSED) { > mIsDone = true; > } > >- if (Available()) { >+ if (Available() || mIsDone) { > Http2Stream *consumer = mPushStream->GetConsumerStream(); > > if (consumer) { > LOG3(("Http2PushTransactionBuffer::WriteSegments notifying connection " >- "consumer data available 0x%X [%u]\n", >- mPushStream->StreamID(), Available())); >+ "consumer data available 0x%X [%u] done=%d\n", >+ mPushStream->StreamID(), Available(), mIsDone)); > mPushStream->ConnectPushedStream(consumer); > } > } > > return rv; > } > > uint32_t >diff --git a/netwerk/protocol/http/SpdyPush3.cpp b/netwerk/protocol/http/SpdyPush3.cpp >--- a/netwerk/protocol/http/SpdyPush3.cpp >+++ b/netwerk/protocol/http/SpdyPush3.cpp >@@ -279,23 +279,23 @@ SpdyPush3TransactionBuffer::WriteSegment > count, countWritten); > if (NS_SUCCEEDED(rv)) { > mBufferedHTTP1Used += *countWritten; > } > else if (rv == NS_BASE_STREAM_CLOSED) { > mIsDone = true; > } > >- if (Available()) { >+ if (Available() || mIsDone) { > SpdyStream3 *consumer = mPushStream->GetConsumerStream(); > > if (consumer) { > LOG3(("SpdyPush3TransactionBuffer::WriteSegments notifying connection " >- "consumer data available 0x%X [%u]\n", >- mPushStream->StreamID(), Available())); >+ "consumer data available 0x%X [%u] done=%d\n", >+ mPushStream->StreamID(), Available(), mIsDone)); > mPushStream->ConnectPushedStream(consumer); > } > } > > return rv; > } > > uint32_t >diff --git a/netwerk/protocol/http/SpdyPush31.cpp b/netwerk/protocol/http/SpdyPush31.cpp >--- a/netwerk/protocol/http/SpdyPush31.cpp >+++ b/netwerk/protocol/http/SpdyPush31.cpp >@@ -277,23 +277,23 @@ SpdyPush31TransactionBuffer::WriteSegmen > count, countWritten); > if (NS_SUCCEEDED(rv)) { > mBufferedHTTP1Used += *countWritten; > } > else if (rv == NS_BASE_STREAM_CLOSED) { > mIsDone = true; > } > >- if (Available()) { >+ if (Available() || mIsDone) { > SpdyStream31 *consumer = mPushStream->GetConsumerStream(); > > if (consumer) { > LOG3(("SpdyPush31TransactionBuffer::WriteSegments notifying connection " >- "consumer data available 0x%X [%u]\n", >- mPushStream->StreamID(), Available())); >+ "consumer data available 0x%X [%u] done=%d\n", >+ mPushStream->StreamID(), Available(), mIsDone)); > mPushStream->ConnectPushedStream(consumer); > } > } > > return rv; > } > > uint32_t
Attachment #8506398 - Attachment is obsolete: true
Attachment #8549994 - Flags: review+
Attached patch INTERDIFF — — Splinter Review
this is the interdiff of patch 2 from its previous r+'d version until now - this is rolled into the r?'d patch.
Comment on attachment 8549998 [details] [diff] [review] INTERDIFF Review of attachment 8549998 [details] [diff] [review]: ----------------------------------------------------------------- Will r+ the new part 2, but that's dependent on fixing the things here (especially that duplicated code bit) ::: netwerk/protocol/http/Http2Stream.cpp @@ +171,5 @@ > if (rv == NS_BASE_STREAM_WOULD_BLOCK && !mTxInlineFrameUsed) > mRequestBlockedOnRead = 1; > > + // A transaction that had already generated its headers before it was > + // queued at the spdy level (due to concurrency concerns) may not call nit: s/spdy/session/ ::: netwerk/protocol/http/SpdyStream31.cpp @@ +157,5 @@ > + OnReadSegment("", 0, &wasted); > + mSegmentReader = nullptr; > + } > + > + // A transaction that had already generated its headers before it was This seems to be duplicate code. ::: testing/xpcshell/moz-http2/moz-http2.js @@ +92,5 @@ > + resp : null, > + > + onTimeout : function onTimeout() { > + this.resp.writeHead(200); > + this.resp.end("It's all good 75ms."); nit: 750, not 75 ::: testing/xpcshell/moz-spdy/moz-spdy.js @@ +80,5 @@ > + resp : null, > + > + onTimeout : function onTimeout() { > + this.resp.writeHead(200); > + this.resp.end("It's all good spdy 75ms."); nit: 750, not 75
Comment on attachment 8549995 [details] [diff] [review] h2 push hit not subject to max_concurrent 2/2 Review of attachment 8549995 [details] [diff] [review]: ----------------------------------------------------------------- Dependent on fixes mentioned in interdiff comment, r=me
Attachment #8549995 - Flags: review?(hurley) → review+
(In reply to Nicholas Hurley [:hurley] from comment #28) > > > This seems to be duplicate code. > good catch - thanks!
Attachment #8549995 - Attachment is obsolete: true
Attachment #8550374 - Flags: review+
Depends on: 1124717
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: