Skip to content

High memory usage for upgraded http requests #11868

Closed
Closed
High memory usage for upgraded http requests#11868
Labels
httpIssues and PRs related to the http subsystem.memoryIssues and PRs related to Node.js memory management or memory footprint.

Description

@lpinca
lpinca
opened on Mar 15, 2017
  • 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.

Activity

  1. lpinca
    added
    httpIssues and PRs related to the http subsystem.
    on Mar 15, 2017

  2. lpinca commented on Mar 19, 2017

    @lpinca
    lpinca
    on Mar 19, 2017
    MemberAuthor

    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:

    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?

  3. lpinca
    added a commit that references this issue on Mar 22, 2017

    http: avoid retaining unneeded memory

    0100984
  4. jasnell
    added a commit that references this issue on Mar 22, 2017

    http: avoid retaining unneeded memory

    e0a9ad1
  5. lpinca
    added
    memoryIssues and PRs related to Node.js memory management or memory footprint.
    on Mar 25, 2017

  6. lpinca commented on Mar 25, 2017

    @lpinca
    lpinca
    on Mar 25, 2017
    MemberAuthor

    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

  7. mscdex commented on Mar 26, 2017

    @mscdex
    mscdex
    on Mar 26, 2017
    Contributor

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

  8. lpinca commented on Mar 26, 2017

    @lpinca
    lpinca
    on Mar 26, 2017
    MemberAuthor

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

  9. lpinca commented on Mar 26, 2017

    @lpinca
    lpinca
    on Mar 26, 2017
    MemberAuthor
    $ ./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.

  10. mscdex commented on Mar 26, 2017

    @mscdex
    mscdex
    on Mar 26, 2017
    Contributor

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

  11. lpinca commented on Mar 26, 2017

    @lpinca
    lpinca
    on Mar 26, 2017
    MemberAuthor

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

  12. mscdex commented on Mar 26, 2017

    @mscdex
    mscdex
    on Mar 26, 2017
    Contributor

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

  13. lpinca commented on Apr 6, 2017

    @lpinca
    lpinca
    on Apr 6, 2017
    MemberAuthor

    Closing as everything has been addressed here.

  14. lpinca
    closed this as completedon Apr 6, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    httpIssues and PRs related to the http subsystem.memoryIssues and PRs related to Node.js memory management or memory footprint.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions