Improve TLS flow control

[bennoleslie]

Currently when a TLS stream is paused the underlying socket is not
paused. This results in a lot of data buffering within the OpenSSL
context.

This leads to two problems: firstly it destroys one of the
advantages of streaming as excessive memory is used; secondly it
doesn't provide push back to the client, so the client is unaware
of the throttling, which is undesirable.

This patch solves this by directly pausing (and resuming) the
underlying socket.

[ry]

This seems okay to me. Are you experiencing this data buffering?

@mranney @dannycoates are you guys okay with this?

[bennoleslie]

Yeah I was seeing this in my test systems (may not end up being a problem on production I guess). I can try and generate an isolated test case if it is useful, but really it is just a case of doing req.pause(), wait some time req.resume() and you get flooded with a lot more data than just the socket buffer. (And if you poke around in the data structures you can call _internallyPendingBytes() to see that it is all buffered inside openssl data structures).

[mranney]

We aren't doing pause on HTTPS right now, mostly because we don't use HTTPS for bulk transfers yet.

This change sounds excellent though, because I'd like to start moving more things over HTTPS.

[koichik]

There are two subclasses of CryptoStream. CleartextStream and EncryptedStream.
It is only CleartextStream that should call Socket.pause() (EncryptedStream does not have a socket property).

However, I think that write() should return a false rather than call Socket.pause() directly.

• CleartextStream.write() shoud return a false if EncryptedStream is paused.
• EncryptedStream.write() shoud return a false if CleartextStream is paused.

Then, Stream.pipe() calls Socket.pause() if CleartextStream is paused.

Also:

• CleartextStream.resume() should eventually emit 'drain' event on EncryptedStream.
• EncryptedStream.resume() should eventually emit 'drain' event on CleartextStream.

[koichik]

@bnoordhuis - On the master (not apply 815b672), the test (1fe318b) is very slow with libuv (similar to #1643 ?).

with legacy:

$ time ./node --use-legacy test/simple/test-tls-pause.js 
DEBUG: paused

node.js:208
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
AssertionError: false == true
    at Array.send (/home/koichik/git/joyent/node/test/simple/test-tls-pause.js:55:16)
    at EventEmitter._tickCallback (node.js:200:26)

real    0m3.327s
user    0m3.070s
sys 0m0.590s

with libuv:

$ time ./node test/simple/test-tls-pause.js 
DEBUG: paused

node.js:208
        throw e; // process.nextTick error, or 'error' event on first tick
              ^
AssertionError: false == true
    at Array.send (/home/koichik/git/joyent/node/test/simple/test-tls-pause.js:55:16)
    at EventEmitter._tickCallback (node.js:200:26)

real    0m35.399s
user    0m37.750s
sys 0m2.210s

[bnoordhuis]

@koichik - confirmed, will look into it.

[mikeal]

+1

isn't the performance difference likely related to libuv perf and not this change specifically.

[bnoordhuis]

@koichik - libuv writes out much more data before the assertion is triggered:

legacy:  1966080 bytes received/sent ( 1.9 MB)
uv:     58605568 bytes received/sent (55.9 MB)

So that's why it's taking 10x as long. libuv is holding up pretty well, it's pumping around 3x as much data per second as legacy.

[koichik]

@bnoordhuis - Wow, it is great!

[koichik]

815b672 has fixed #1643 (?)

master (416c14f):

$ time ./node test/pummel/test-https-large-response.js
build body...done
got request
response!
..................................................................................................................................................................................................
expected:  12582912
     got:  12582912

real    0m9.565s
user    0m9.970s
sys 0m0.710s

815b672:

$ time ./node test/pummel/test-https-large-response.js
build body...done
got request
response!
.................................................................................................................................................................................................
expected:  12582912
     got:  12582912

real    0m2.073s
user    0m1.840s
sys 0m0.410s

[ry]

confirmed! 815b672 looks good to me but I wish it had some comments.

[koichik]

@ry - Done. Please review 491f72c.

[ry]

@koichik LGTM

[koichik]

@ry - Thanks!

[koichik]

@bennoleslie - Thanks for the report. Fixed a different way.

[bennoleslie]

@koichik - thanks for the fix, yours is much more elegant. I tried to fix it the way you did, but I couldn't get it working, so I'm glad you made a much better fix.