Memory leak using http's request/get/clientRequest and closures

[vvo]

Using nodejs 0.6.15 on Linux 64bits Debian Wheezy.

I made a small test file that is leaking memory when using http.get.
It seems that callback functions are retained.

The test just use http.get on a lot of google domains.

https://gist.github.com/2488897

var
  http = require('http'),
  extensions = ['com', 'ac', 'ad', 'ae', 'com.af', 'com.ag', 'com.ai', 'am', 'it.ao', 'com.ar', 'as', 'at', 'com.au', 'az', 'ba', 'com.bd', 'be', 'bf', 'bg', 'com.bh', 'bi', 'bj', 'com.bn', 'com.bo', 'com.br', 'bs', 'co.bw', 'com.by', 'com.bz', 'ca', 'com.kh', 'cc', 'cd', 'cf', 'cat', 'cg', 'ch', 'ci', 'co.ck', 'cl', 'cm', 'cn', 'com.co', 'co.cr', 'com.cu', 'cv', 'cz', 'de', 'dj', 'dk', 'dm', 'com.do', 'dz', 'com.ec', 'ee', 'com.eg', 'es', 'com.et', 'fi', 'com.fj', 'fm', 'fr', 'ga', 'gd', 'ge', 'gf', 'gg', 'com.gh', 'com.gi', 'gl', 'gm', 'gp', 'gr', 'com.gt', 'gy', 'com.hk', 'hn', 'hr', 'ht', 'hu', 'co.id', 'iq', 'ie', 'co.il', 'im', 'co.in', 'io', 'is', 'it', 'je', 'com.jm', 'jo', 'co.jp', 'co.ke', 'com.kh', 'ki', 'kg', 'co.kr', 'com.kw', 'kz', 'la', 'com.lb', 'com.lc', 'li', 'lk', 'co.ls', 'lt', 'lu', 'lv', 'com.ly', 'co.ma', 'md', 'me', 'mg', 'mk', 'ml', 'mn', 'ms', 'com.mt', 'mu', 'mv', 'mw', 'com.mx', 'com.my', 'co.mz', 'com.na', 'ne', 'com.nf', 'com.ng', 'com.ni', 'nl', 'no', 'com.np', 'nr', 'nu', 'co.nz', 'com.om', 'com.pa', 'com.pe', 'com.ph', 'com.pk', 'pl', 'pn', 'com.pr', 'ps', 'pt', 'com.py', 'com.qa', 'ro', 'rs', 'ru', 'rw', 'com.sa', 'com.sb', 'sc', 'se', 'com.sg', 'sh', 'si', 'sk', 'com.sl', 'sn', 'sm', 'so', 'st', 'com.sv', 'td', 'tg', 'co.th', 'com.tj', 'tk', 'tl', 'tm', 'to', 'com.tn', 'com.tr', 'tt', 'com.tw', 'co.tz', 'com.ua', 'co.ug', 'co.uk', 'us', 'com.uy', 'co.uz', 'com.vc', 'co.ve', 'vg', 'co.vi', 'com.vn', 'vu', 'ws', 'co.za', 'co.zm', 'co.zw'],
  nbloop = 9, nblaunch = 2, done = 0, todo = nblaunch*nbloop*extensions.length;

console.log('We should do '+ todo +' requests');

// show memused and progress while running
setInterval(status, 5000);status();

// 2 launch
loop();setTimeout(loop, 10000);

function loop() {
  console.log('Starting a new request loop');
  for(var i = 0; i < nbloop; i++) {
    getall();
  }
}

function getall() {
  // creates a big buffer
  var megabig = new Big();

  // this should not trigger a memory leak but it does when using http.get
  function cb() {
    done+=1;
    return megabig;
  }

  extensions.forEach(function(ext) {
    // using setTimeout instead of http.get shows no mem leak
    // setTimeout(cb, 10);

    http.get({
      hostname: 'www.google.' + ext,
      pathname: '/index.html?' + Math.random(),
      port: 80,
      protocol: 'http:'
    }, cb);
  });
}

function Big() {
  this.yo = (new Buffer(1 * 1024 * 1024 * 3)).toString();
}

function status() {
  console.log((process.memoryUsage().heapUsed/1024/1024).toFixed() + 'MB used');
  console.log('Done: '+ done +'/'+ todo);
  if (done === todo) {
    console.log('all requests done, memory should be collected by now ?')
  }
}

After all requests are done, I get ~105MB used memory that will not be freed.
Calling cb() with setTimeout does not leak so it is http related.

I'm using a lot of # domains because memory usage goes up the more domains I have.

Using https://github.com/c4milo/node-webkit-agent (great great tool) I was able to get this retain paths:

And after looking at http.js it seems I solved this, you decide.

[vvo]

Results:

node 0.6.15

105MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

node HEAD

88MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

node HEAD with FIX e138f76

10MB used
Done: 3510/3510
all requests done, memory should be collected by now ?

No more (big) leak, tests ok. I guess there are some other leaks, will debug more but right now this is a good fix I guess.

Also I do no think we need .on but .once should be enough.

[bnoordhuis]

Thanks for the detailed bug report. I'm trying to reproduce it but without much luck. I see an initial jump to 90-110 MB RSS but it comes down again once the script is done and settles around 15-30 MB (0.6.15 and master both), which is what you'd expect for a live but mostly idle VM.

What happens if you add a if (typeof gc === 'function') gc() at the top of status() and run your script with --expose-gc?

[bnoordhuis]

By the way, does it also happen when you run it against a local server? Here is a script you can test against:

for (var i = 0; i < 1000; ++i)
  require('net').createServer(onConnection).listen(30000 + i);

function onConnection(conn)
{
  conn.write('HTTP/1.0 200 OK\r\nServer: test\r\n\r\n',
             conn.destroy.bind(conn));
}

[bnoordhuis]

Okay, I'm getting more and more convinced that the HTTP client leaks memory. I've added a benchmark in 12a90e9 that spawns a couple of servers and clients. Memory usage of the servers is relatively stable (RSS grows and shrinks as you would expect) but with the clients it keeps growing and growing.

[bnoordhuis]

I tried your patch from #3181 but I'm afraid it didn't make an appreciable difference. To be continued.

[Filirom1]

Hi,

I made the gist simpler (no need of google servers :) ): https://gist.github.com/2518326 , and test it without and with #3181

Without #3181

[romain@myhost trace-memory-leaks]$ node --expose-gc gistfile1.js 
We should do 5 requests
3MB used
Done: 0/5, not yet GC: 0
24MB used
Done: 5/5, not yet GC: 5
all requests done, memory should be collected by now ?
24MB used
Done: 5/5, not yet GC: 5
all requests done, memory should be collected by now ?

With #3181

[romain@myhost trace-memory-leaks]$ node --expose-gc gistfile1.js 
We should do 5 requests
3MB used
Done: 0/5, not yet GC: 0
24MB used
Done: 5/5, not yet GC: 0
all requests done, memory should be collected by now ?
3MB used
Done: 5/5, not yet GC: 0
all requests done, memory should be collected by now ?

[vvo]

@bnoordhuis I was measuring heapUsed and not rss. Although I do not know how to distinguish rss/heapUsed/heapTotal.

About #3181. I'm pretty sure we should not .on('response', cb) but .once('reponse', cb).
Why would we wait for more than one response event on an ClientRequest object?
I saw that @isaacs is working on https://github.com/joyent/node/tree/http-memleak so I decided to do some testing on this branch.

Here are my results using his branch, then applying #3181.
Using a much simpler test file using some modified work from @Filirom1 : https://gist.github.com/2488897
This test now creates 100MB Buffers, an HTTP Server and do 30 request in localhost.

I'm outputing all memory usage information. I only hid some /path informations on my system.

Using joyent/node/tree/http-memleak :

vvo@think-vvo [01:08:46] [~/node] [http-memleak]
-> % git branch                                                                              
* http-memleak
  master
vvo@think-vvo [01:08:49] [~/node] [http-memleak]
-> % ./out/Release/node -v                                                                   
v0.6.17-pre
vvo@think-vvo [01:08:56] [~/node] [http-memleak]
-> % time ./out/Release/node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 113MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 113MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
^C./out/Release/node   0.18s user 0.06s system 0% cpu 25.686 total

rss: 111MB, heapUsed: 103MB, heapTotal: 105MB

Then, applying #3181 and configure and make and re-run :

vvo@think-vvo [01:11:54] [~/node] [http-memleak *]
-> % git branch
* http-memleak
  master
vvo@think-vvo [01:11:56] [~/node] [http-memleak *]
-> % ./out/Release/node -v
v0.6.17-pre
vvo@think-vvo [01:11:57] [~/node] [http-memleak *]
-> % git diff   
diff --git a/lib/http.js b/lib/http.js
index 9aaff7f..e8ca291 100644
--- a/lib/http.js
+++ b/lib/http.js
@@ -1014,7 +1014,7 @@ function ClientRequest(options, cb) {
   var method = self.method = (options.method || 'GET').toUpperCase();
   self.path = options.path || '/';
   if (cb) {
-    self.on('response', cb);
+    self.once('response', cb);
   }

   if (!Array.isArray(options.headers)) {
vvo@think-vvo [01:13:40] [~/node] [http-memleak *]
-> % time ./out/Release/node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 11MB, heapUsed: 3MB, heapTotal: 5MB
Done: 30/30
All requests done, memory should be collected
^C./out/Release/node   0.18s user 0.05s system 1% cpu 17.587 total

rss: 11MB, heapUsed: 3MB, heapTotal: 5MB

Using node 0.6.16 :

vvo@think-vvo [01:22:07] [~/node] [http-memleak *]
-> % node -v
v0.6.16
vvo@think-vvo [01:22:09] [~/node] [http-memleak *]
-> % time node /memleak.js
We should do 30 requests
rss: 13MB, heapUsed: 4MB, heapTotal: 6MB
Done: 0/30
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 114MB, heapUsed: 104MB, heapTotal: 108MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
rss: 111MB, heapUsed: 103MB, heapTotal: 105MB
Done: 30/30
All requests done, memory should be collected
^Cnode /memleak.js  0.18s user 0.06s system 1% cpu 22.355 total

rss: 111MB, heapUsed: 103MB, heapTotal: 105MB

The fact that the mem goes up to >100MB without #3181 is due to always keeping a reference to the latest callback request done by an http agent in memory. That request callback holds a reference to a 100MB Buffer.

I bet this is due to the .on('reponse') which is never cleared and should be. Once we use .once('response') and a response event is emitted there is no more callback reference hold.

Hope I'm not mistaking.

I'm sure there are other mem leaks using http request since it didn't solved all our production memleaks. Will try to find more...

[Filirom1]

Hi,

For me the branch https://github.com/joyent/node/tree/http-memleak works well, but I still have a memory leak when I use setTimeout

http.get({
  hostname: 'localhost',
  pathname: '/index.html?' + Math.random(),
  port: 3000,
  protocol: 'http:'
}, cb).on('error', function(e) {
  cb(e);
}).setTimeout(10, function(){
  console.log('nothing here')
})

https://gist.github.com/2577565

[isaacs]

We've been tracking down an error that looks suspiciously like this at @joyent that @mranney is encountering at @Voxer.

If bfe9cdb doesn't fix it, then we'll look into other things.

e25611e is not acceptable, because it puts http-specific logic into FreeList, which is not where it belongs.