High memory usage for upgraded http requests #11868

lpinca · 2017-03-15T17:17:39Z

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.

The text was updated successfully, but these errors were encountered:

lpinca · 2017-03-19T09:03:34Z

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:

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:

Remove the additional event listeners added in the HTTP server (timeout, error, drain). This makes sense.
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?

Prevent the events listeners of the sockets obtained with the HTTP upgrade mechanism from retaining unneeded memory. Refs: nodejs#11868

Prevent the events listeners of the sockets obtained with the HTTP upgrade mechanism from retaining unneeded memory. Ref: #11868 PR-URL: #11926 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>

lpinca · 2017-03-25T15:21:59Z

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 · 2017-03-26T10:07:54Z

@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 · 2017-03-26T10:22:40Z

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

lpinca · 2017-03-26T13:56:37Z

$ ./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 · 2017-03-26T19:59:52Z

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

lpinca · 2017-03-26T20:15:30Z

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

mscdex · 2017-03-26T20:23:35Z

@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.

Prevent the events listeners of the sockets obtained with the HTTP upgrade mechanism from retaining unneeded memory. Ref: nodejs#11868 PR-URL: nodejs#11926 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>

lpinca · 2017-04-06T06:47:57Z

Closing as everything has been addressed here.

lpinca added the http Issues or PRs related to the http subsystem. label Mar 15, 2017

lpinca mentioned this issue Mar 20, 2017

http: avoid retaining unneeded memory #11926

Closed

2 tasks

lpinca added a commit to lpinca/node that referenced this issue Mar 22, 2017

http: avoid retaining unneeded memory

0100984

Prevent the events listeners of the sockets obtained with the HTTP upgrade mechanism from retaining unneeded memory. Refs: nodejs#11868

lpinca added the memory Issues and PRs related to the memory management or memory footprint. label Mar 25, 2017

lpinca mentioned this issue Mar 26, 2017

lib: use Object.create(null) directly #11930

Closed

2 tasks

lpinca mentioned this issue Apr 4, 2017

events: don't keep arrays with a single listener #12043

Closed

3 tasks

lpinca closed this as completed Apr 6, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

High memory usage for upgraded http requests #11868

High memory usage for upgraded http requests #11868

lpinca commented Mar 15, 2017 •

edited

Loading

lpinca commented Mar 19, 2017 •

edited

Loading

lpinca commented Mar 25, 2017

mscdex commented Mar 26, 2017 •

edited

Loading

lpinca commented Mar 26, 2017

lpinca commented Mar 26, 2017

mscdex commented Mar 26, 2017

lpinca commented Mar 26, 2017 •

edited

Loading

mscdex commented Mar 26, 2017 •

edited

Loading

lpinca commented Apr 6, 2017

High memory usage for upgraded http requests #11868

High memory usage for upgraded http requests #11868

Comments

lpinca commented Mar 15, 2017 • edited Loading

lpinca commented Mar 19, 2017 • edited Loading

lpinca commented Mar 25, 2017

mscdex commented Mar 26, 2017 • edited Loading

lpinca commented Mar 26, 2017

lpinca commented Mar 26, 2017

mscdex commented Mar 26, 2017

lpinca commented Mar 26, 2017 • edited Loading

mscdex commented Mar 26, 2017 • edited Loading

lpinca commented Apr 6, 2017

lpinca commented Mar 15, 2017 •

edited

Loading

lpinca commented Mar 19, 2017 •

edited

Loading

mscdex commented Mar 26, 2017 •

edited

Loading

lpinca commented Mar 26, 2017 •

edited

Loading

mscdex commented Mar 26, 2017 •

edited

Loading