My question is whether this is a nodejs garbage collector bug? Or is this somehow expected?
Running node v14.15.0 on Windows.
While working on an answer for this question involving WeakRef objects, I discovered a curious thing about garbage collection that seems like a possible bug. An object assigned to a variable declared within a for loop is not getting garbage collected even after that let variable is out of scope of the for loop. The variable of interest here is named element and here's the loop it is in. It is just the object from the last iteration of the loop that is not getting GCed (the one that element last pointed to):
// fill all the arrays and the cache
// and put everything into the holding array too
for (let i = 0; i < numElements; i++) {
let arr = new Array(lenArrays);
arr.fill(i);
let element = { id: i, data: arr };
// temporarily hold onto each element by putting a
// full reference (not a weakRef) into an array
holding.push(element);
// add a weakRef to the Map
cache.set(i, new WeakRef(element));
}
Then, a few lines of code later, we clear the array holding with this:
holding.length = 0;
You would think that after this loop is finished and after holding has been cleared, that all the values of element from that loop should be eligible for GC. The only references to them any more are via WeakRef objects (which don't prevent GC).
And, indeed, if I let nodejs have some idle time, all the objects except the very last one created by the for loop are indeed GCed. But, the last one is not. If I add element = null to the end of the for loop, then that last one then does get GCed. So, somehow nodejs is not clearing the refcnt on the variable that element last pointed to, even though element is now out of scope.
So, you can see the entire code here (you can drop this into a file and run it in nodejs yourself):
'use strict';
// to make memory usage output easier to read
function addCommas(str) {
var parts = (str + "").split("."),
main = parts[0],
len = main.length,
output = "",
i = len - 1;
while (i >= 0) {
output = main.charAt(i) + output;
if ((len - i) % 3 === 0 && i > 0) {
output = "," + output;
}
--i;
}
// put decimal part back
if (parts.length > 1) {
output += "." + parts[1];
}
return output;
}
function delay(t, v) {
return new Promise(resolve => {
setTimeout(resolve, t, v);
});
}
function logUsage() {
let usage = process.memoryUsage();
console.log(`heapUsed: ${addCommas(usage.heapUsed)}`);
}
const numElements = 10000;
const lenArrays = 10000;
async function run() {
const cache = new Map();
const holding = [];
function checkItem(n) {
let item = cache.get(n).deref();
console.log(item);
}
// fill all the arrays and the cache
// and put everything into the holding array too
for (let i = 0; i < numElements; i++) {
let arr = new Array(lenArrays);
arr.fill(i);
let element = { id: i, data: arr };
// temporarily hold onto each element by putting a
// full reference (not a weakRef) into an array
holding.push(element);
// add a weakRef to the Map
cache.set(i, new WeakRef(element));
}
// should have a big Map holding lots of data
// all items should still be available
checkItem(numElements - 1);
logUsage();
await delay(5000);
logUsage();
// make whole holding array contents eligible for GC
holding.length = 0;
// pause for GC, then see if items are available
// and what memory usage is
await delay(5000);
checkItem(0);
checkItem(1);
checkItem(numElements - 1);
// count how many items are still in the Map
let cnt = 0;
for (const [index, item] of cache) {
if (item.deref()) {
++cnt;
console.log(`Index item ${index} still in cache`);
}
}
console.log(`There are ${cnt} items that haven't been GCed in the map`);
logUsage();
}
run();
When I run this, I get this output:
{
id: 9999,
data: [
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
... 9900 more items
]
}
heapUsed: 805,544,472
heapUsed: 805,582,072
undefined
undefined
{
id: 9999,
data: [
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999, 9999,
... 9900 more items
]
}
Index item 9999 still in cache
There are 1 items that haven't been GCed in the map
heapUsed: 3,490,168
The two undefined lines are expected. The second logged output of the id:9999 object is not expected. It should also be undefined. And, finding that id:9999 object still in the cache is not expected. It should have been eligible for GC.
One possible theory is that the V8 optimizer is pulling element out of the for loop to avoid having to create it over and over within the loop, but then not making it eligible for GC after the loop is done - essentially hoisting it to the higher scope.
Another theory is that GC isn't always block scope granularity.
Bug or not?