High memory usage for upgraded http requests

[lpinca]

• Version:
  v7.7.3
• Platform:
  macOS/Linux
• Subsystem:
  net/http

I noticed that n socket connections obtained with the HTTP upgrade mechanism use a lot more memory than n socket connections obtained with a plain net server. Consider for example the following test.

net server

'use strict';

const net = require('net');

const headers = [
 'HTTP/1.1 101 Switching Protocols',
 'Connection: Upgrade',
 'Upgrade: foo',
 '',
 ''
].join('\r\n');

let count = 0;
const handler = (socket) => {
 socket.resume();
 socket.write(headers);

 if (++count === 150000) {
 gc();
 const rss = process.memoryUsage().rss;
 console.log(rss / 1024 / 1024);
 }
};

const server = net.createServer({ allowHalfOpen: true });

server.on('connection', handler);
server.listen(3000, () => console.log('listening on *:3000'));

net client

'use strict';

const net = require('net');

const headers = [
 'GET / HTTP/1.1',
 'Connection: Upgrade',
 'Upgrade: foo',
 'Host: localhost:3000',
 '',
 ''
].join('\r\n');

let i = 0;
(function createClient() {
 const socket = net.connect({
 localAddress: `127.0.0.${i % 100 + 1}`,
 port: 3000
 });

 socket.on('connect', () => {
 socket.resume();
 socket.write(headers);

 if (++i === 150000) return;

 createClient();
 });
})();

http server

'use strict';

const http = require('http');

const headers = [
 'HTTP/1.1 101 Switching Protocols',
 'Connection: Upgrade',
 'Upgrade: foo',
 '',
 ''
].join('\r\n');

let count = 0;
const handler = (req, socket, head) => {
 socket.resume();
 socket.write(headers);

 if (++count === 150000) {
 gc();
 const rss = process.memoryUsage().rss;
 console.log(rss / 1024 / 1024);
 }
};

const server = http.createServer();

server.setTimeout(0);
server.on('upgrade', handler);
server.listen(3000, () => console.log('listening on *:3000'));

http client

'use strict';

const http = require('http');

let i = 0;
(function createClient() {
 const req = http.get({
 localAddress: `127.0.0.${i % 100 + 1}`,
 port: 3000,
 headers: {
 'Connection': 'Upgrade',
 'Upgrade': 'foo'
 }
 });

 req.on('upgrade', (res, socket, head) => {
 socket.resume();

 if (++i === 150000) return;

 createClient();
 });
})();

---

The first (net) server uses ~295 MiB of memory while the second (http) ~525 MiB. Shouldn't they use more or less the same amount of memory?

It seems that, in part, the difference is caused by the additional event listeners. If I add

socket.removeAllListeners('drain');
socket.removeAllListeners('error');
socket.removeAllListeners('timeout');

in the upgrade event handler, memory usage drops to ~420 MiB.

[lpinca]

After digging a little more, I noticed that memory usage drops to ~275 MiB if all listeners are removed from the socket.

This made me think that it must be something to do with the default net.Socket event listeners:

• end
• finish
• _socketEnd

I tried to remove and readd them to the socket in the upgrade listener.

const end = socket.listeners('end')[0];
const _socketEnd = socket.listeners('_socketEnd')[0];
const finish = socket.listeners('finish')[0];

socket.removeAllListeners('end');
socket.removeAllListeners('_socketEnd');
socket.removeAllListeners('finish');

socket.once('end', end);
socket.on('_socketEnd', _socketEnd);
socket.on('finish', finish);

and with my big surprise memory usage is now ~300 MiB (the same amount used by the plain net server).

To summarize, in order to make the n socket connections obtained with the HTTP upgrade mechanism use a the same memory of n socket connections obtained with a plain net server, I have to:

1. Remove the additional event listeners added in the HTTP server (timeout, error, drain). This makes sense.
2. Backup, remove and readd the default net.Socket event listeners. This doesn't make sense to me.

Does anyone know and care to explain why this happens?

[lpinca]

A small update here after #11926 which partially fixed this.

It seems that the additional, remaining, memory is retained by instances of EventHandlers.
Consider the following example which only uses instances of EventEmitter.

'use strict';

const EE = require('events');

const _socketEnd = () => {};
const end = () => {};
const finish = () => {};

const ondrain = () => {};
const socketOnClose = () => {};
const socketOnData = () => {};
const socketOnDrain = () => {};
const socketOnEnd = () => {};
const socketOnError = () => {};
const socketOnPause = () => {};
const socketOnResume = () => {};
const socketOnTimeout = () => {};

const arr = [];
for (var i = 0; i < 1000000; i ++) {
 const ee = new EE();

 ee.on('_socketEnd', _socketEnd);
 ee.on('finish', finish);
 ee.once('end', end);
 ee.on('error', socketOnError);
 ee.on('timeout', socketOnTimeout);

 arr.push(ee);
}

setInterval(() => {
 const l = arr.length;
 gc();
 console.log(process.memoryUsage().rss / 1024 / 2014);
}, 30000);

It produces the following results.

$ node -v
v7.7.4
$ node --expose-gc a.js 
127.63455809334657
127.82125124131082
127.89076464746772
127.90863952333665

If I add and remove the additional listeners like it is done in _http_server.js:

$ diff -u a.js b.js 
--- a.js	2017-03-25 16:01:39.000000000 +0100
+++ b.js	2017-03-25 15:34:34.000000000 +0100
@@ -20,12 +20,32 @@
 for (var i = 0; i < 1000000; i ++){
 const ee = new EE();
 
+ // Default socket events listeners.
 ee.on('_socketEnd', _socketEnd);
 ee.on('finish', finish);
 ee.once('end', end);
+
+ // Listeners added in _http_server.js
 ee.on('error', socketOnError);
 ee.on('timeout', socketOnTimeout);
 
+ // Listeners added and removed in _http_server.js
+ ee.on('close', socketOnClose);
+ ee.on('data', socketOnData);
+ ee.on('drain', ondrain);
+ ee.on('drain', socketOnDrain);
+ ee.on('end', socketOnEnd);
+ ee.on('pause', socketOnPause);
+ ee.on('resume', socketOnResume);
+
+ ee.removeListener('close', socketOnClose);
+ ee.removeListener('data', socketOnData);
+ ee.removeListener('drain', ondrain);
+ ee.removeListener('drain', socketOnDrain);
+ ee.removeListener('end', socketOnEnd);
+ ee.removeListener('pause', socketOnPause);
+ ee.removeListener('resume', socketOnResume);
+
 arr.push(ee);
 }

I get

$ node -v
v7.7.4
$ node --expose-gc b.js 
561.4955312810328
561.9324726911618
562.0238331678253
562.051638530288

With #11930 results are more in line with the expected behavior.

$ node -v
v8.0.0-pre
$ node --expose-gc a.js 
355.98808341608736
346.6454816285998
345.3028798411122
345.2154915590864
^C
$ node -v
v8.0.0-pre
$ node --expose-gc b.js 
387.759682224429
389.708043694141
379.2850049652433
378.1708043694141

[mscdex]

@lpinca Did you run those scripts with the various versions of V8 in master? It would be interesting to test master with/without #11930 with each V8: 5.5 (same as v7), 5.6, and recently merged 5.7. This might help narrow down if this was due to some other change in node, due to V8 upgrade, or due to Object.create(null) itself.

[lpinca]

Gonna try with more combinations and post back. It will take some time as compiling takes ages.

[lpinca]

$ ./node-master@9ac363b_5.7_+11930 --expose-gc a.js
347.6683217477656
347.8391261171797
347.38828202581925
349.48560079443894

$ ./node-master@9ac363b_5.7_+11930 --expose-gc b.js
382.33366434955315
382.90963257199604
379.36444885799403
379.3426017874876

$ ./node-master@9ac363b_5.7_-11930 --expose-gc a.js
121.93843098311817
122.1966236345581
121.74577954319761
121.60476663356505

$ ./node-master@9ac363b_5.7_-11930 --expose-gc b.js
552.5898709036743
552.9513406156901
551.5829195630586
551.5431976166832

$ ./node-master@e0bc5a7_5.6_+11930 --expose-gc a.js
346.8599801390268
347.36246276067527
345.68023833167825
345.6524329692155

$ ./node-master@e0bc5a7_5.6_+11930 --expose-gc b.js
381.4975173783515
382.04170804369414
378.14299900695136
377.97815292949355

$ ./node-master@e0bc5a7_5.6_-11930 --expose-gc a.js
121.15392254220457
121.92055610724925
120.99304865938431
120.95928500496524

$ ./node-master@e0bc5a7_5.6_-11930 --expose-gc b.js
554.5620655412115
555.1062562065541
551.7378351539226
551.578947368421

$ ./node-v7.7.4+11930 --expose-gc a.js
130.5700099304866
131.23733862959284
129.02879841112215
128.95729890764648

$ ./node-v7.7.4+11930 --expose-gc b.js
555.0625620655412
555.6981132075472
552.1966236345581
552.1251241310824

$ ./node-v7.7.4-11930 --expose-gc a.js
119.14597815292949
119.46573982125125
118.95729890764648
118.96921549155908

$ ./node-v7.7.4-11930 --expose-gc b.js
553.811320754717
554.5719960278053
551.9443892750745
551.9602780536246

$ ./node-v7.5.0+11930 --expose-gc a.js
132.76663356504469
133.54319761668322
129.33267130089374
129.2651439920556

$ ./node-v7.5.0+11930 --expose-gc b.js
550.4270109235352
550.6276067527309
550.1767626613704
550.1231380337637

$ ./node-v7.5.0-11930 --expose-gc a.js
122.38927507447865
122.91161866931479
120.1449851042701
120.06752730883814

$ ./node-v7.5.0-11930 --expose-gc b.js
553.837140019861
554.720953326713
550.5124131082423
550.4389275074478

With V8 5.4 and 5.5 there is no difference. Something changed in 5.6.

[mscdex]

I'm wondering if 5.6 is when the Object.create(null) pattern changed to producing dictionary mode objects.

[lpinca]

@mscdex not sure how to see that https://codereview.chromium.org/2430273007.

[mscdex]

@lpinca It appears it was first available in 5.6.144 (see the github mirror).

Additionally, you can check the output of

var obj = Object.create(null);
console.log(%HasFastProperties(obj));

with the --allow-natives-syntax command line flag. It should show 'false' if the commit exists in the V8 release.