When Flow Control Goes Wild in SPDY/3

‹prev | My Chain | next›

Last night, I witnessed SPDY flow control. And it was glorious.

Well that might be a stretch, but it was pretty cool. I sent a SPDY SETTINGS frame to Chrome indicating that the data transfer window was very low, which ensured that Chrome would use flow control. I then sent back the necessary WINDOW_UPDATE to Chrome as data was POSTed from browser to server, allowing data to flow.

Tonight, I would like to see what happens in the opposite direction. What happens when the data being sent from a spdy/3 server (flow control is new in spdy/3) is too large for the data window?

For that, I need a large image. One of the scanned documents from The SPDY Book should suffice:

➜  express-spdy-test  ls -lh public/images 
total 836K
-rw-r--r-- 1 chris chris 830K Apr 30 22:56 pipelining.jpg

I add the image to the homepage of my simple spdy-ized express.js, restart the server and load the page up:

That broken image icon is not the result of HTML-gone-wrong. At first, it starts to load, but quickly goes broken after that. Checking the SPDY tab of Chrome's chrome://net-internals, I see that the image is, indeed requested. Indeed, transfer of the data seems to start out OK:

SPDY_SESSION_SYN_STREAM
--> flags = 1
--> :host: localhost:3000
    :method: GET
    :path: /images/pipelining.jpg
    :scheme: https
    :version: HTTP/1.1
    accept: */*
    accept-charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
    accept-encoding: gzip,deflate,sdch
    accept-language: en-US,en;q=0.8
    cookie: [value was stripped]
    referer: https://localhost:3000/
    user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/536.9 (KHTML, like Gecko) Chrome/20.0.1115.1 Safari/536.9
--> id = 7
SPDY_SESSION_SYN_REPLY
--> flags = 0
--> :status: 200
    :version: HTTP/1.1
--> id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
...

The browser ends up seeing 29 of those 1300 byte DATA frames before it issues a WINDOW_UPDATE:

...
SPDY_SESSION_SENT_WINDOW_UPDATE
--> delta = 37700
--> stream_id = 7
...

Theis WINDOW_UPDATE is informing the server that 37700 bytes, which happens to be all of the data sent so far (29 * 1300 = 37700), has been processed and that more data may been sent.

Currently, node-spdy is WINDOW_UPDATE ignorant, so these frames go quietly ignored:

Express server listening on port 3000 in development mode
Unknown type:  unknown: 9

The WINDOW_UPDATE from the browser is ignored and the server keeps right on sending data, which is what the browser wants anyway.

Another 31 data frames are sent, each sized 1300 bytes. There is also a stray 660 byte frame, for a grand total of 40960 bytes. And then Chrome issues another WINDOW_UPDATE indicating that all of the data received so far has been processed:

....
SPDY_SESSION_RECV_DATA
--> flags = 0
--> size = 1300
--> stream_id = 7
SPDY_SESSION_SENT_WINDOW_UPDATE
--> delta = 40960
--> stream_id = 7
...

This is followed by another 25 full-sized frames and one 660 byte frame, along with a WINDOW_UPDATE for delta = 33160. The same pattern is repeated once more, resulting in another WINDOW_UPDATE for delta = 33160.

After each of these WINDOW_UPDATE frames, the internal data transfer window that the server should have is 64kb, the default data transfer window in SPDY. The server sends 33kb or so of data, the window goes down, then the browser signals that is has read all pending data and the window goes back to 64kb.

And then something interesting happens.

Not 29, 25, or 31 DATA frames are sent. This time, 60 full DATA frames are sent, plus two 660 sized DATA frames. This is a total of 79320 bytes that are sent from the server to the browser, which is well past the 64kb transfer window.

At this point, Chrome does the right thing by telling the server that something has gone wrong:

SPDY_SESSION_SEND_RST_STREAM
--> description = "Negative recv window size"
--> status = 1
--> stream_id = 7

Chrome is no longer listening, but node-spdy goes right on sending the data--to no avail. The result is a broken image. Actually, it is not so much broken as ignored.

My takeaway from this is that spdy/3 conversations had better be flow control aware otherwise there is going to be a lot of ignored data. So I will get started on that tomorrow.


Day #372