memory leak

[rpedela]

I am pretty sure I found a major memory leak. It seems to be related to the gzipResponse and bodyParser plugins. I use node-memwatch to inspect the memory usage and force a garbage collection.

Version Info

ubuntu: 12.04
node: 0.10.4
restify: 2.6.0

Server

var fs = require('fs');
var memwatch = require('memwatch');
var restify = require('restify');

var hd = null;

function startDiff(req, res, next) {
    memwatch.gc();
    hd = new memwatch.HeapDiff();
    return next();
}

function endDiff(req, res, next) {
    memwatch.gc();
    var diff = hd.end();

    console.log('before: ' + diff.before.size);
    console.log('after: ' + diff.after.size);
    console.log('change: ' + diff.change.size);
    console.log('---------------------');

    return next();
}

var server = restify.createServer();

// removing either plugin also exhibits the memory leak
// remove both plugins and no memory leak
server.use(restify.gzipResponse());
server.use(restify.bodyParser());

server.get('/', [
    startDiff,
    function(req, res, next) {
        // large-file.json is a just a large JSON file, content does not matter
        var data = fs.readFileSync('large-file.json'));
        res.send(JSON.parse(data));
        return next();
    },
    endDiff,
]);

server.listen(4001, function() {
    console.log('listening at ' + server.url);
});

Client

curl --compressed http://localhost:4001 > /dev/null

Output after 3 client calls, with memory leak

before: 5.99 mb
after: 175.48 mb
change: 169.5 mb
---------------------
before: 175.83 mb
after: 318.21 mb
change: 142.38 mb
---------------------
before: 318.4 mb
after: 460.75 mb
change: 142.35 mb
---------------------

Output after 3 client calls, with no memory leak

before: 5.87 mb
after: 147.82 mb
change: 141.94 mb
---------------------
before: 5.36 mb
after: 147.86 mb
change: 142.5 mb
---------------------
before: 5.4 mb
after: 147.88 mb
change: 142.48 mb
---------------------

[rpedela]

You can add all the other bundled plugins with the order specified in the docs and the behavior is still the same. I also tried Node versions 0.10.16 and 0.8.25 with similar results.

[mcavage]

Hmm, that's interesting. I'll take a look, but sadly I'm on the road a
bunch right now - so it's definitely going to be some significant lag
before I get to it.

On Wed, Aug 21, 2013 at 2:57 PM, Ryan Pedela notifications@github.comwrote:

I also tried Node versions 0.10.16 and 0.8.25 with similar results.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/431#issuecomment-23053731
.

[rpedela]

Okay. Yeah I plan to dig deeper into exactly where it is.

[mcavage]

If I were to guess, something is holding node buffers. If you haven't
tried smartos, this is much easier to debug there:
http://dtrace.org/blogs/bmc/2012/05/05/debugging-node-js-memory-leaks/(that's
what I will do when I get to this).

On Wed, Aug 21, 2013 at 3:25 PM, Ryan Pedela notifications@github.comwrote:

Okay. Yeah I plan to dig deeper into exactly where it is.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/431#issuecomment-23055348
.

[rpedela]

Cool, thanks. I will take a look at SmartOS.

[rpedela]

I used node-heapdump and looked at the dumps using Chrome. I took a heap snapshot in the startDiff function and made 3 client calls.

With only gzip response
The first snapshot looked normal of course. The second snapshot had an extra instance of ServerResponse with its body and data set to the content of the large JSON file. The third snapshot has two extra instances of ServerResponse with their body and data set. So it looks like the response variable is not being freed. The object's retaining tree suggests it has something to do with handledGzip in the gzip plugin code.

With only body parser
The same behavior happens, but in the third snapshot there is still only one extra ServerResponse instance. So it is more like the first ServerResponse is never freed, but the rest are. In addition, IncomingMessage instances are quite large in the second and third snapshots. The object's retaining tree suggests that the response and incoming message are pointing to each other.

I am not too experienced looking at heap retaining trees, but hopefully I have pointed you in the right direction.

[rpedela]

Digging deeper with the gzip case, I think it has to do with all the circular binding going on. I commented out all the handledGzip code and then the retaining tree showed references from writeHead. I commented that out and then the tree showed references to Gzip.

[mcavage]

So, is the bodyParser leaking as well or is it just GZIP? I should have
some time this week to look into this.

On Fri, Aug 23, 2013 at 5:47 PM, Ryan Pedela notifications@github.comwrote:

Digging deeper with the gzip case, I think it has to do with all the
binding going on. I commented out all the handledGzip code and then the
retaining tree showed references from writeHead. I commented that out and
then the tree showed references to Gzip.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/431#issuecomment-23195938
.

[rpedela]

I think bodyParser has a bug where the current request keeps a reference to the previous response. The memory is eventually freed though. Gzip creates a leak that keeps growing. I have worked around the gzip bug by compressing the responses myself.

[thisandagain]

Spent some time trying to track this down in production. I can verify that gzip looks to be the culprit. I haven't had a moment to dig into the plugin yet though.

[drfloob]

Update for v2.6.2: bodyParser alone doesn't seem to have a leak, but gzipResponse leaks with and without bodyParser. The memory usage eventually stabilizes.

listening at http://0.0.0.0:4001
before: 4.68 mb
after: 212.16 mb
change: 207.49 mb
---------------------
before: 148.4 mb
after: 300.24 mb
change: 151.84 mb
---------------------
before: 236.44 mb
after: 300.26 mb
change: 63.82 mb
---------------------
before: 92.42 mb
after: 300.24 mb
change: 207.82 mb
---------------------
before: 236.44 mb
after: 300.26 mb
change: 63.81 mb
---------------------
before: 236.45 mb
after: 300.26 mb
change: 63.81 mb
---------------------
... more of the same ...

[framerate]

Scratch that. Turns out it was node-newrelic (the tool I was using to monitor) that was causing the leak. Restify appears fine in my tests!

[marcosrmendezaw]

I was able to reproduce this memory leak with a minor adjustment. I am switching back to express until this is resolved. I will paste the test code below. You can test the results with restify and also enable express to see the difference.

---

var fs = require('fs');
var memwatch = require('memwatch');
var restify = require('restify');
//var express = require('express');
var path = require('path');

var hd = null;

function startDiff(req, res, next) {
memwatch.gc();
hd = new memwatch.HeapDiff();
return next();
}

function endDiff(req, res, next) {
setTimeout(function(){
memwatch.gc();
var diff = hd.end();

    console.log('before: ' + diff.before.size);
    console.log('after: ' + diff.after.size);
    console.log('change: ' + diff.change.size);
    console.log('---------------------');

}, 10000);


return next();

}

var server = restify.createServer();
//var server = express();

// removing either plugin also exhibits the memory leak
// remove both plugins and no memory leak
//server.use(restify.gzipResponse());
//server.use(restify.bodyParser());

var filename = path.join(__dirname,'../../data/Microsoft_Press_eBook_Programming_Windows_Store_Apps_2nd_Edition_2nd_Preview.pdf');
console.log(filename);

server.get('/', [
startDiff,
function(req, res, next) {
var data = fs.readFileSync(filename);
res.send(data);
res.end();
return next();
},
endDiff
]);

server.listen(4001, function() {
console.log('listening at ' + server.url);
});

[marcosrmendezaw]

Btw, I was using 2.7.0 and upgraded to 2.8.1 due to the same issue.