Stream interleaving

[cyrus-and]

Let's say I have a dummy script like this:

var spdy = require('spdy');
var fs = require('fs');

var options = {
    key: fs.readFileSync(__dirname + '/keys/spdy-key.pem'),
    cert: fs.readFileSync(__dirname + '/keys/spdy-cert.pem'),
    ca: fs.readFileSync(__dirname + '/keys/spdy-ca.pem'),
};

var html = fs.readFileSync('index.html');
var imgs = [];

for (var i = 0; i < 10; i++) {
    imgs[i] = fs.readFileSync(i + '.jpg');
}

function logic(req, res) {
    if (req.url === '/') {
        res.writeHead(200, {'Content-Type': 'text/html'});
        res.end(html);
    } else if (req.url.match(/\/[0-9]/)) {
        var n = req.url[1];
        res.writeHead(200, {'Content-Type': 'image/jpeg'});
        res.end(imgs[n]);
    }
}

spdy.createServer(options, logic).listen(8443);

Where index.html is just a list of 10 <img /> tag, and each image is ~800K.

Am I wrong if I expect to see in the SPDY event log in chrome://net-internals that the SPDY_SESSION_RECV_DATA events of the various streams (10 in this case) interleave?

What I see is instead that, firstly each stream is created:

t=1370706783266 [st=  263]    SPDY_SESSION_SYN_STREAM
                              --> fin = true
                              --> :host: xxxxxxxxxxxxxxxxxx.xx:8443
                                  :method: GET
                                  :path: /0.jpg
                                  :scheme: https
                                  :version: HTTP/1.1
                                  accept: */*
                                  accept-encoding: gzip,deflate,sdch
                                  accept-language: it-IT,en-US;q=0.8
                                  cache-control: no-cache
                                  pragma: no-cache
                                  referer: https://xxxxxxxxxxxxxxxxxx.xx:8443/
                                  user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.110 Safari/537.36
                              --> stream_id = 3
                              --> unidirectional = false
t=1370706783267 [st=  264]    SPDY_SESSION_SYN_STREAM
                              --> fin = true
                              --> :host: xxxxxxxxxxxxxxxxxx.xx:8443
                                  :method: GET
                                  :path: /1.jpg
                                  :scheme: https
                                  :version: HTTP/1.1
                                  accept: */*
                                  accept-encoding: gzip,deflate,sdch
                                  accept-language: it-IT,en-US;q=0.8
                                  cache-control: no-cache
                                  pragma: no-cache
                                  referer: https://xxxxxxxxxxxxxxxxxx.xx:8443/
                                  user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.110 Safari/537.36
                              --> stream_id = 5
                              --> unidirectional = false
t=1370706783280 [st=  277]    SPDY_SESSION_SYN_STREAM
                              --> fin = true
                              --> :host: xxxxxxxxxxxxxxxxxx.xx:8443
                                  :method: GET
                                  :path: /2.jpg
                                  :scheme: https
                                  :version: HTTP/1.1
                                  accept: */*
                                  accept-encoding: gzip,deflate,sdch
                                  accept-language: it-IT,en-US;q=0.8
                                  cache-control: no-cache
                                  pragma: no-cache
                                  referer: https://xxxxxxxxxxxxxxxxxx.xx:8443/
                                  user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.110 Safari/537.36
                              --> stream_id = 7
                              --> unidirectional = false
[...]

and then SPDY_SESSION_RECV_DATA events arrive serially:

t=1370706783332 [st=  329]    SPDY_SESSION_SYN_REPLY
                              --> fin = false
                              --> :status: 200 OK
                                  :version: HTTP/1.1
                                  content-type: image/jpeg
                              --> stream_id = 3
                              --> unidirectional = false
t=1370706783498 [st=  495]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8184
                              --> stream_id = 3
t=1370706783498 [st=  495]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 3
t=1370706783620 [st=  617]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 3
[...]
t=1370706790103 [st= 7100]    SPDY_SESSION_SYN_REPLY
                              --> fin = false
                              --> :status: 200 OK
                                  :version: HTTP/1.1
                                  content-type: image/jpeg
                              --> stream_id = 5
                              --> unidirectional = false
t=1370706790234 [st= 7231]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8184
                              --> stream_id = 5
t=1370706790234 [st= 7231]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 5
t=1370706790355 [st= 7352]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 5
[...]
t=1370706796835 [st=13832]    SPDY_SESSION_SYN_REPLY
                              --> fin = false
                              --> :status: 200 OK
                                  :version: HTTP/1.1
                                  content-type: image/jpeg
                              --> stream_id = 7
                              --> unidirectional = false
t=1370706796970 [st=13967]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8184
                              --> stream_id = 7
t=1370706796970 [st=13967]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 7
t=1370706797103 [st=14100]    SPDY_SESSION_RECV_DATA
                              --> fin = false
                              --> size = 8192
                              --> stream_id = 7
[...]

That sounds strange to me since one goal of SPDY is to exactly avoid the HOL blocking of HTTP pipelining.

And this doesn't happen with Apache mod_spdy.

How can you explain this behavior?

[indutny]

Thanks, fixed in sdpy@1.10.0