high tls memory usage (rss)

[ChALkeR]

https.request leaks in this example:

'use strict';
var https = require('https');
var options = {
    hostname: 'google.com'
};
function next() {
    setTimeout(iterate, 10);
}
function onError(error) {
    console.log(error);
}
function noop() {}
function onResponse(res) {
    console.log('statusCode: ', res.statusCode);
    res.on('data', noop);
    res.on('end', next);
}
function iterate() {
    console.log(JSON.stringify(process.memoryUsage()));
    console.log('iterating...');
    https.request(options, onResponse).
        on('error', onError).
        end();
};
iterate();

rss grows over time, heapUsed remains about constant (~30m).
This could be reproduced with all released iojs versions that I tried v1.0.1 and v1.8.1.

Node v0.12.2 behaves better in this testcase: rss grows to about 100m, but goes down periodically (I wouldn't call that a perfect behaviour, let's call that «fine»).

53ba494, dad73f6 and 8a83eba are three sequental commits.
53ba494 is fine (as 0.12), dad73f6 fails to build, 8a83eba leaks.
dad73f6 is «upgrade v8 to 3.31.74.1» with 831 files changed, 104394 insertions(+), 21427 deletions(-).
Node v0.12.2 could be fine because it still uses v8 3.28.73.
io.js 1.0.0/1.1.0 + shared v8 3.30.33.16 behaves fine (the same as 0.12).

All the testcases and massif data are at http://oserv.org/bugs/iojs/memory0/

[ChALkeR]

Could be reproduced with wreck:

'use strict';
var wreck = require('wreck');
function callback(error, res, payload) {
    if (error) {
        console.log(error);
        return;
    }
    console.log('statusCode: ', res.statusCode);
    setTimeout(iterate, 10);
}
function iterate() {
    console.log(JSON.stringify(process.memoryUsage()));
    console.log('iterating...');
    wreck.get('https://google.com/', callback);
};
iterate();

[ChALkeR]

I found a work-around for that particular testcase.
It's not applicable in real world, i think, but it could give some ideas on where the bug is.

'use strict';

var requests = 20;
var total = 1000;
// If `maxSockets` is less then `requests`, then RSS stops growing from some point.
var maxSockets = 10;

var https = require('https');
var agent = new https.Agent();
agent.maxSockets = maxSockets;
var count = 0;
var options = {
    agent: agent,
    hostname: 'google.com'
};
function next() {
    setTimeout(iterate, 0);
}
function onError(error) {
    console.log(error);
}
function noop() {}
function onResponse(res) {
    console.log('statusCode: ', res.statusCode);
    res.on('data', noop);
    res.on('end', next);
}
function iterate() {
    console.log(JSON.stringify(process.memoryUsage()));
    if (count >= total) process.exit();
    console.log('iterating... ' + ' num: ' + (++count));
    https.request(options, onResponse).
        on('error', onError).
        end();
};
for (var i = 0; i < requests; i++) iterate();

In this example, if agent.maxSockets is less than the number of https.requests being executed at the same time, then RSS stops growing.
If only one https.request is being executed at every moment, then it can't help.
agent.maxSockets = 10 and 20 calls to https.request is ok
agent.maxSockets = 10 and 10 calls to https.request is not ok

http://oserv.org/bugs/iojs/memory0/test-agent.js — testcase.
http://oserv.org/bugs/iojs/memory0/test-agent.txt — results.

http://oserv.org/bugs/iojs/memory0/test-fast.js could be used to reproduce this a bit faster (20 requests at the same time).

[ChALkeR]

cc @indutny

[ChALkeR]

http://oserv.org/bugs/iojs/memory0/test-fast.js could be used to reproduce this a bit faster (20 requests at the same time).

[ChALkeR]

io.js 1.8.1:

node 0.12.2:

The time that those two were running for could be different, but you could clearly see the difference still.

[ChALkeR]

Actually, it goes down after manually calling gc().
If I call gc() manually every 100 requests, RSS does not go above 70 MiB.

Could it be that gc() is never called?

[ChALkeR]

Until a full gc run (calling gc()), TLSWrap native objects get never deleted.
Full gc is not called automatically, probably because v8 thinks that incremental gc works fine (well, heapUsed is ~30 MiB most of the time).

Full gc is not called automatically until ~500MiB rss (without valgrind/massif) is reached.

[ChALkeR]

But even when rss reaches ~500MiB and full gc is called (deleting TLSWrap objects), rss memory usage does not go down.

[indutny]

@ChALkeR I have modified the test case to work with localhost server (partly because I'm on 3G internet, partly because I'm not so patient). And it appears to me that it grows up to 1.1gb very fast, then drops to 800mb and then stays around 600mb for 50 parallel connections.

The breaking point (1.1gb) happens at 21373 iteration for me. Have you tried waiting that long?

[indutny]

I have a fix for lowering 1.1gb, btw. Will push a PR tomorrow.

[ChALkeR]

Lowering to which point? If agent.maxSockets is lower than the number of parallel connections, rss somehow stabilizes at ~40 MiB. What's the difference in this case?

Just checked — in this case TLSWrap objects are reused.
For 20 parallel connections and 1000 total requests:

• with agent.maxSockets = 10 — only 10 TLSWrap objects are created,
• with agent.maxSockets = 17 — only 17 TLSWrap objects are created,
• with agent.maxSockets = 18 — 21 TLSWrap objects are created,
• with agent.maxSockets = 19 — 83 TLSWrap objects are created,
• with agent.maxSockets = 20 — 1000 TLSWrap objects are created.

[indutny]

@ChALkeR to 400mb as far as I remember. Anyway, do you see that everything is getting collected after growing to 1gb?

[ChALkeR]

No.

For me, full gc kicks in at 500 MiB. But it does not lower rss memory usage, it just (almost) stops growing.

statusCode:  302
{"rss":556351488,"heapTotal":75819520,"heapUsed":25609128}
iterating...  num: 21408
statusCode:  302
{"rss":556351488,"heapTotal":75819520,"heapUsed":25723656}
iterating...  num: 21409
statusCode:  302
{"rss":556351488,"heapTotal":75819520,"heapUsed":25751024}
iterating...  num: 21410

[indutny]

@ChALkeR I wasn't talking about GC in general. I was talking about the point where all accumulated TLSWraps are collected and RSS lowers significantly.