Possible memory leak with class Error

[sgeraud]

The following works well, but replacing line new BigObj() by new Error() results in a very large heap snapshot, even if heapdump.writeSnapshot(); triggers garbage collection.

var async = require("async");
var heapdump = require("heapdump");

var seq = [];
for (var i = 0; i < 50000; i++) {
    seq[i] = i;
}

function BigObj() {
    this.message = "hello";
    this.x = [];
    for (var i = 0; i < 1000; ++i) {
        this.x.push("mlkj");
    }
}

heapdump.writeSnapshot();
async.mapSeries(seq, function (x, cb) {
    var err = new BigObj();
    // var err = new Error();
    setTimeout(function () {
        err.message;
        cb(null);
    }, 0);
}, function () {
    heapdump.writeSnapshot();
    process.exit();
});

Snapshots for BigObj:

-rw-r--r--  1 sgeraud  staff   1,7M 27 jan 16:32 heapdump-195670438.615838.heapsnapshot
-rw-r--r--  1 sgeraud  staff   6,4M 27 jan 16:33 heapdump-195739533.54126.heapsnapshot

Snapshots for Error:

-rw-r--r--  1 sgeraud  staff   1,7M 27 jan 16:34 heapdump-195804014.440544.heapsnapshot
-rw-r--r--  1 sgeraud  staff    66M 27 jan 16:35 heapdump-195873113.196591.heapsnapshot

Observed with node v0.12.7 and node v5.5.0 on Mac OS X 10.11.2
and node v5.41. on Ubuntu 14.04.3

[sgeraud]

NB: We didn't observe such a difference when running a similar code in Chrome DevTools (but maybe Chrome measuring tools are not the same as heapdump?)

[bnoordhuis]

I don't really see anything out of the ordinary here. The .stack property of the Error object retains the captured stack trace. A stack trace is on the order of one kilobyte, so 50,000 stack traces are about 48 MB.

If you're wondering why the snapshot for BigObj is so much smaller, the elements in the embedded array all point to the same string literal ("mlkj") so the object graph is really simple. If you change it to this.x.push("mlkj" + i), you'll get a much bigger snapshot (also because of all the strings you're creating, of course.)

[sebastien-mignot]

@bnoordhuis an array containing 1000 refs to the same immutable string literal is on the order of one kilobyte. so it should have the same problem.
I'll test your idea anyway to see if that increase a lot the heap, but even if it does, that would mean the local variable "err" is not correctly garbage collected (possibly because of the closure), which would be an even bigger nodejs bug...

[bnoordhuis]

an array containing 1000 refs to the same immutable string literal is on the order of one kilobyte. so it should have the same problem.

In memory, but the presentation in the snapshot is - in principle - much simpler, it's just the same edge many times over. That said, I just ran the example and I ended up with a 1.3 GB snapshot...

I'll test your idea anyway to see if that increase a lot the heap, but even if it does, that would mean the local variable "err" is not correctly garbage collected (possibly because of the closure), which would be an even bigger nodejs bug...

Yes, the closures keep the objects alive but I don't see how that is a bug. How would you expect it to work otherwise? The GC can't free the err objects when the closures are still reachable.

[sebastien-mignot]

@bnoordhuis For the difference between the size in ram and the representation in the snapshot, that's true, but we opened the snapshot each time in chrome dev tool where it shows the actual size on disc. It was different that 1.7 and 6.4, but in the same order, so I don't think that's the pb.

And for the GC part : the closure is not reachable after the setTimeout is executed ! That's why we did this convoluted exemple with async. This code shouldn't have any non-cleanable objects in memory when we call heapdump the second time. Else all the async non blocking server apps writen in nodejs would have big problems...

[sgeraud]

That said, I just ran the example and I ended up with a 1.3 GB snapshot...

@bnoordhuis If I change the test to this.x.push("mlkj" + i), the snapshot has roughly the same size (6.3 MB) so the strings seem to be garbage collected. How can you get a 1.3 GB snapshot?

[bnoordhuis]

I modified the test case to not use async (but kept the setTimeout) so all 50,000 elements are retained. async was one moving part too many for clear analysis. Fun fact: the version with new Error() is only 59 MB big.

[ChALkeR]

If you change it to this.x.push("mlkj" + i)

Nope, that's not it. This code should be used to get unique strings:

var t = 0;
function BigObj() {
    this.message = "hello";
    this.x = [];
    for (var i = 0; i < 1000; ++i) {
        this.x.push("mlkj" + (t++));
    }
}

There are a lot of BigObj instances.

[bnoordhuis]

I played around with it some more and as far as I can determine, the issue is simply retainment through closures and the seq array. If you rewrite the test case to clear those before snapshotting, the snapshot is 1.9 MB in both cases. There's no core bug here that I can see.

[sebastien-mignot]

@bnoordhuis "seq" don't have any references to the functions in the first exemple, why would not cleaning "seq" prevent the gc to collect stuff ? Could you post your code please ?

[bnoordhuis]

"seq" don't have any references to the functions in the first exemple, why would not cleaning "seq" prevent the gc to collect stuff ?

seq is not the big one but it adds a few KB to the snapshot unless cleared. (Half-truth: V8 can normally determine when it's no longer reachable but it depends on how you write your code. V8 isn't great at escape analysis.)

Could you post your code please ?

Here you go:

var seq = [];
for (var i = 0; i < 50000; i++) seq[i] = i;

function BigObj() {
  this.message = "hello";
  this.x = [];
  for (var i = 0; i < 1000; ++i) this.x.push("mlkj");
}

seq = seq.map(function() {
  return new BigObj();
  // return new Error();
});
// process.seq = seq;  // retain
seq = [];

require("../../node-heapdump").writeSnapshot();

If you uncomment the assignment to process.seq, you get large snapshots.

[sebastien-mignot]

@bnoordhuis Your map just creates an array of BigObj. So yeah if you keep a reference to this array, it can't be GCed, else it can.
That not at all the same thing as our exemple, in which the seq array don't point in any way to the closure or to the BigObjs/Errors. So the closures and the BigObjs and the Errors SHOULD be GCed when the sequence has finished executing. And indeed the BigObjs are GCed !!! But not the Errors !! Which can't be explained in any way !!.

@ChALkeR the strings are really besides the point, BigObj could be an array of 1000 null's, and it's enough to show the bug. 50000 arrays of 1000 null are already big enough to show if they were GCed or not. (as you can see in bnoordhuis exemple, when they are not GCed, it's already BIG, 1.3G)

@bnoordhuis if you absolutely want to get rid of the async.series, you should write the following, and pray that in 10 mins all the 50000 setTimeouts will be finished ; but it's really not serious for testing, and I think using async doesn't make the code too strange to be accepted here (and it's something than really used by everyone really often now)

var heapdump = require("heapdump");

function BigObj() {
    this.message = "hello";
    this.x = [];
    for (var i = 0; i < 1000; ++i) {
        this.x.push("mlkj");
    }
}

heapdump.writeSnapshot();

for (var i = 0; i < 50000; i++) {
    (function () {
        var err = new Error();
        // var err = new BigObj();
        setTimeout(function () {
            err.message;
        }, 0);
    })();
}

setTimeout(function () {
    heapdump.writeSnapshot();
}, 600000);

[bnoordhuis]

For me, your script produces snapshots in both cases that are:

1. 1.6 and 1.7 MB big with v5.x, and
2. 1.8 and 1.9 MB big with master (which is at V8 4.8.271.17 and logs more metadata.)

[bnoordhuis]

Maybe try running with --trace_gc --trace_gc_verbose - the last log message should be along the lines of [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested] and reclaim most of the old space.

[sebastien-mignot]

@bnoordhuis With which script did you mesure those numbers please ? The first script given by sgeraud or the last one with the simple for-loop that I gave as exemple ?
Because if it's the first one, that would be very troubling given the multiple versions and OS on which we tried it...

[bnoordhuis]

The last one.

[sebastien-mignot]

@bnoordhuis Yes, I gave it as an exemple of how you could modify your first exemple to be closer to ours, but I didn't run it, as I said it's really not practical to test with this, puting a temporisation on the second dump and all. The first script (the one inside the issue description) is the one that we have tested on many config and that reproduces the bug every time.

I don't know what the process usually is to report bug her, I wouldn't want to presume anything; but I truely feel that the first script is a really standard nodejs usecase. All our production code is done like this: get the request in a route, start a series of asynchronous calls (in parallel or series depending on what we are doing), then respond to the client, and all this on a always-on express server. And one of our wrapper creates a "new Error" to capture the stack in case something goes wrong, then is (supposedly) GCed when the async.series/parallel is completed. And we have a memory leak !
The fact that in the first script there is a leak with "new Error" and not with "new BigObj", seems for me to be a proof of a true problem with node.

[bnoordhuis]

Okay, can you come up with a minimal test case that demonstrates the memory leak (if that what it is) without depending on third-party modules?

[sgeraud]

This example shows the memory leak:

var heapdump = require("heapdump");

var t = 0;

function BigObj() {
    this.message = "hello";
    this.x = [];
    for (var i = 0; i < 1000; ++i) {
        this.x.push("foo" + (++t));
    }
}

var execSeries = function (seq, callback) {
    if (seq.length === 0) {
        callback();
        return;
    }
    (seq.shift())(function () {
        execSeries(seq, callback);
    });
};

var makeObj = function (cb) {
    // var err = new BigObj();
    var err = new Error();
    setTimeout(function () {
        err.message;
        cb();
    });
};

var seq = [];
for (var i = 0; i < 50000; i++) {
    seq[i] = makeObj;
}

heapdump.writeSnapshot();

execSeries(seq, function () {
    heapdump.writeSnapshot();
    process.exit();
});

With BigObj:

-rw-r--r--  1 sgeraud  staff   3,5M 28 jan 11:20 heapdump-263355060.990933.heapsnapshot
-rw-r--r--  1 sgeraud  staff   1,7M 28 jan 11:21 heapdump-263435114.329606.heapsnapshot

With Error:

-rw-r--r--  1 sgeraud  staff   3,5M 28 jan 11:22 heapdump-263497342.999060.heapsnapshot
-rw-r--r--  1 sgeraud  staff    50M 28 jan 11:23 heapdump-263566965.849143.heapsnapshot

[bnoordhuis]

Thanks, I can reproduce now but I'm not sure it's a solvable issue. First off, the problem lies with V8, not node.js; it's not an issue we have direct control over.

What happens is that the .stack property retains the environment. If you replace the call to new Error with e.g. var err = {}; Error.captureStackTrace(err), you get the same issue, unless you do err.stack = null afterwards.

If you run the test with --stack_trace_limit=3, you end up with small snapshots. With --stack_trace_limit=4 - big snapshots, i.e., it's the depth of the stack trace that makes it retain the environment.

It's possible it's been fixed or alleviated in V8 4.9+ but I haven't tested that. You may want to consider filing a bug over at https://bugs.chromium.org/p/v8/issues/list.

[sebastien-mignot]

@bnoordhuis Thank's a lot for all the time you took investigating this issue !
I filed a bug in the chromium tracker, here is the link in case you want to follow it : https://bugs.chromium.org/p/v8/issues/detail?id=4714
I'll post an update on this issue anyway if the guys from chromium solve the problem.

[bnoordhuis]

Talk about coincidence: I was going to post that I suspect this is v8:2340 but I see the issue you reported was closed today as a duplicate of that selfsame issue.

I'll close this issue. The V8 team thinks it's not a bug so there isn't much we can do.

[sebastien-mignot]

Yes indeed. Thank's for your help on this issue @bnoordhuis !