vm: --expose-gc breaks gc and crashes with --max-old-space-size

[ChALkeR]

Extracted from #3113.
Verified using 4.1.0 (pre-built, from nodejs.org) and 4.1.2 (Archlinux packages).

Testcase is at the very top of #3113, a fancier version here (but it works with the original one):

'use strict';

var vm = require('vm');

var total = 0;
var last = 0;
function foo() {
    vm.runInNewContext('(_$_v.length-1)', {
        '_$_v': [
        { category: 'reference',
            author: 'Nigel Rees',
            title: 'Sayings of the Century',
            price: 8.95 },
        { category: 'fiction',
            author: 'Evelyn Waugh',
            title: 'Sword of Honour',
            price: 12.99 },
        { category: 'fiction',
            author: 'Herman Melville',
            title: 'Moby Dick',
            isbn: '0-553-21311-3',
            price: 8.99 },
        { category: 'fiction',
            author: 'J. R. R. Tolkien',
            title: 'The Lord of the Rings',
            isbn: '0-395-19395-8',
            price: 22.99 }
        ]
    });
    total++;
    last++;
    if (total % 10 === 0) {
        console.log("After", total, "iterations:", parseInt(process.memoryUsage().heapTotal / 1024 / 1024), "MB");
    }
    setImmediate(foo);
}
function count() {
    console.log('Last: ' + (last / 5) + ' ops/sec');
    last = 0;
}

setInterval(count, 5000);
foo();

The speed starts from ~28 ops/sec in all cases.

1. When run without flags — works, heapTotal stabilizes at ~1260 MiB. The speed stabilizes at ~25 ops/sec.
2. When run with --expose-gc (without changing the code to trigger gc()), heapTotal stabilizes at about ~1430 MiB. The speed stabilizes at ~10 ops/sec.
3. When run with --max-old-space-size=32, heapTotal stabilizes at about ~48 MiB. The speed stabilizes at ~26.6 ops/sec.
4. When run with --max-old-space-size=32 --expose-gc, node crashes after ~30 iterations with FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory.
5. When run with --max-old-space-size=200 --expose-gc, node crashes after ~280 iterations with FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory.
6. When run with --max-old-space-size=1000 --expose-gc, node crashes after ~1290 iterations with FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory (after hanging for about a minute at 0.5 ops/sec).

Yes, I know that the above speed measurement isn't accurate, it doesn't matter much.

[ChALkeR]

/cc @domenic

[domenic]

Does this repro without vm shenanigans?

Probably /cc @nodejs/v8 instead of just me.

[ChALkeR]

@domenic To the moment, I wasn't able to reproduce this without using vm. No guarantees, though, because I haven't tried very hard.

[ChALkeR]

Something has improved recently, but this is still not fixed.

On v5.5.0 and v4.2.6 — does not crash, the speed start from ~600 ops/sec.

1. With --max-old-space-size=32 --expose-gc the speed does not drop and remains stable at ~600 ops/sec.
2. With --max-old-space-size=100 --expose-gc the speed remains stable at ~100 ops/sec.
3. With --max-old-space-size=32 --expose-gc the speed drops to ~2 ops/sec.

--expose-gc still significantly affects the results (there is no slowdown without it, and the speed is stable at ~1200 ops/sec for all --max-old-space-size values).

On v5.0.0 the results were the same as in the initial post (the same as in v4.1.0).

[asaworld]

I have been diving into memory management with vm and new context. This looks as simple as each new context created has the gc global added to it after the context is create. I guess the gc has a pointer to the context and with expose-gc the context has a pointer to the gc. None of these contexts ever get cleaned up. This can simple be solved with the context created as a variable 'c'. Then after runInNewContext is executed c.gc = null; Memory back to normal.

Maybe createContext should not assign global gc.

[ChALkeR]

@asadenton Thanks. This is clearly vm-related, then.

[mhdawson]

Have you identified the code (file/source lines) in Node.js which does what you describe in you earlier comment ?

[asaworld]

Sorry, I have not. Once I discovered I could clear the vm vars and it all worked I moved on with that.

[targos]

@ChALkeR is this still an issue ?

I get the following numbers with v6.3.0:

1. Without flags: stable at ~ 2500 ops/sec
2. With --expose-gc: stable at ~ 2300 ops/sec
3. With --max-old-space-size=32 --expose-gc: stable at ~ 2400 ops/sec

[ChALkeR]

Yes, looks fixed to me. Nice!