For obvious reasons, I have done most of my SPDY experimentation in the Chrome browser. That has continued to be the case as I have explored flow control in the latest version 3 of the protocol specification.
As I found out the other night, not only is Chrome not the only game in SPDY town, but it may not even lay claim to the best tool for debugging SPDY implementations. Despite this, I have been exploring spdy/3 exclusively with Chrome because Firefox only supports spdy/2.
It turns out that the Firefox nightlies actually include experimental spdy/3. So tonight, I hope to kick the tires on Firefox spdy/3.
I start by downloading a recent build from the esteemed Patrick McManus:
➜ Downloads wget https://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/mcmanus@ducksong.com-a695632fc51a/try-linux64/firefox-15.0a1.en-US.linux-x86_64.tar.bz2I don't know if this is Patrick or Mozilla, but in the same FTP directory is a list of checksums for each download. That should be more common than it is—I hate running software without a simple way to double check that it has not been altered. To be sure, it is no guarantee, but it gives me some piece of mind.
Anyhow, I check the SHA512 signature:
➜ Downloads sha512sum firefox-15.0a1.en-US.linux-x86_64.tar.bz2 073fbf9827b120b4bc313553683ef2c8cee719d154fd2670b2380078c284c16ab97e6223619620e98dccfb76328415587a26bdff302f19571834fa8d382c8d33 firefox-15.0a1.en-US.linux-x86_64.tar.bz2Indeed, that is the signature on the FTP server, so I proceed.
I extract the build into my
$HOME/src directory:➜ src tar jxf ~/Downloads/firefox-15.0a1.en-US.linux-x86_64.tar.bz2And fire up Firefox:
➜ firefox ./firefoxI am greeted with an add-ons update dialog:
And eventually the start screen:
So I appear to be running the latest and greatest. Nice!
Next up, I hit my simple express.js test app that is powered by node-spdy and... it works:
Of course, I have no idea if that is spdy/3 (or even spdy/2). I could try installing one of the extensions that tells me if SPDY is being used, but it is more fun to use Firefox's awesome logging facilities. So I shut down the browser and re-run with the usual logging environment options:
➜ firefox export NSPR_LOG_MODULES=nsHttp:5,nsSocketTransport:5,nsHostResolver:5 ➜ firefox export NSPR_LOG_FILE=/tmp/log.txt ➜ firefox ./firefoxIn
/tmp/log.txt, I see that it is, indeed, using spdy/3:... 351270656[7fef27440e10]: nsHttpConnection::EnsureNPNComplete 7feefdae2200 negotiated to 'spdy/3' ...Unfortunately, the page is not quite loading:
Only one of the images is only partially loaded. I do not know how the page loaded previously. My guess would be that Firefox had ignored SPDY, making an SSL connection instead. That or I had previously cached those images. At any rate, it is not working now, so...
To the log files!
I actually do not see any information in the log file about Firefox sending WINDOW_UPDATE frames to facilitate flow control. I would guess that it is because there seem to be a lot of DATA frames from both images in the log. In the end, I see what looks like an error:
... nsHttpTransaction::ProcessData [this=3313fe30 count=1300] nsHttpTransaction::HandleContent [this=3313fe30 count=1300] nsHttpTransaction::HandleContent [this=3313fe30 count=1300 read=1300 mContentRead=185940 mContentLength=-1] nsSocketInputStream::Read [this=32eda2f0 count=8] calling PR_Read [count=8] nsHttpChannel::OnDataAvailable [this=7f9c4618b800 request=7f9c381ae5c0 offset=184640 count=1300] sending status notification [this=7f9c4618b800 status=804b0006 progress=185940/18446744073709551615] PR_Read returned [n=-1] ErrorAccordingToNSPR [in=-5961 out=804b0014] nsSocketTransport::OnMsgInputClosed [this=32eda1c0 reason=804b0014] SpdySession3 7f9c37936000 buffering frame header read failure 804b0014 nsHttpConnection::CloseTransaction[this=3311e020 trans=37936000 reason=804b0014] SpdySession3::Close 7f9c37936000 804B0014 ...I troubleshoot this in node-spdy, scattering
console.log() statements about in a vain search for WINDOW_UPDATE frames. I never see a single WINDOW_UPDATE from Firefox. Unless Firefox is completely ignoring the spdy/3 spec, the only way that I can see this being possible is if Firefox begins the SPDY conversation by setting an impossibly high initial window size. So I log this value:
Connection.prototype.setDefaultTransferWindow = function(settings) {
if (settings.initial_window_size) {
console.log("settings.initial_window_size: " + settings.initial_window_size);
this.transferWindowSize = settings.initial_window_size;
// ...
}
};And, sure enough, in response to a Firefox connection, node-spdy sees:settings.initial_window_size: 268435456I have spent most of my time in flow control looking at smaller receive windows, not large ones. So I am unsure if the fault here lies with node-spdy or Firefox.
I will continue investigating tomorrow.
Day #383
hey chris, thanks for looking at the build. It's a pedantic difference that what you're looking at is just a sandbox build and not really a nightly. Nightly's have been checked into the main tree and undergone code review, which spdy/3 hasn't yet. (but soon!) But the important thing is we're working on it.
ReplyDeleteYes, firefox generally uses an rwin of 256MB because the only reason to limit download speeds is to reduce buffering in the client when multiplexing across consumers of different speeds (or if you don't have enough ram for a full tcp rwin, but that's not interesting to a desktop client). If you're running out of window for any other reason then you're just slowing stuff down!
Places we would expect to use a rwin throttle but currently don't yet include plugin consumers that aren't consuming data as fast as it is coming in (the API currently forces the buffering onto the plugin, so that's sort of a non-issue - but it would be better to push it back to the sender), and in conjunction with server-push where we would want to slow down the pushed data until it was checked against the local cache. (I haven't implemented that one yet - one of the implications of that is that we might start with a small rwin from settings and grow it quickly beyond the initial size - make sure you're ready for that).
do you see another case where it would make sense for a client to be sporting rwin's smaller than the network BDP? I'd be interested in your thoughts.
However, I am concerned about 1 thing. FF should generate a window update every time it has consumed 64KB of data (even though there is still tons of room in the window) as long as it hasn't seen the fin for that stream yet. Given that information, do you think you should have seen a window update but did not? I'd be interested in a test case for next week if that's a mismatch. I think you and I are the only people to have ever run this code at this point, so a bug is certainly possible.
oh, lastly "SpdySession3 7f9c37936000 buffering frame header read failure 804b0014" is an incredibly obtuse way of saying that the server closed the connection on the spdy session.
I was thinking about this more while I was mowing the lawn :)
ReplyDeleteThe firefox log would be interesting to see. For every data frame recvd you should see a line like
"SpdySession3::UpdateLocalRwin ptr 0xID count".. ignore the ptr, ID is the stream ID, and count is the number of bytes in the data frame.
If that data packet genereates a window update from firefox you should also see a line like
"SpdySession3::UpdateLocalRwin Ack ptr 0x%ID delta".. ptr and ID are the same as last time, but delta is the size of the delta in the window update being created. it may be bigger than the count from the preceding packet because ff doesn't generate an update off of every single receive (that's just a waste of upstream bandwidth when there is so much receive window available) - there must be >= 65536 unack'd bytes before it will do so (without having received a fin, because there's no point once that happens).
if you've got a public url that can demonstrate it, that would be the easiest route to a solution.