Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Node Memory Usage for Concat Strings

I have the following code to test out the memory use for node vm:

setInterval(()=>console.log(process.memoryUsage()),1000);

( ()=> {

    const MAXTIMES = 10000000;

    let a = ( ()=> {
        let res = "";
        for(let i=0; i<MAXTIMES; i++){
            res = res + "X";
        }
        return res;
    })();


})();

//Uncomment this to give enough time for GC and check top command. 
//Not needed with setInterval in the beginning
//setTimeout(()=>{}, 10000);

top command shows vm uses ~420M memory.

When I change the max value of i to 100000000(100M), I was expecting the memory usage to be around 620M (420M +2 bytes * 100M), but it got to a stunning 3300~4000M. What is going on here? Is GC not picking up the temp strings in the loop?

I tried to use var to make sure i is hoisted, but it is the same result.

EDIT1: Updated code to full code with comment

EDIT2

I run the code too on Firefox, Safari and Chrome JS console on a random tab, and it has similar issues. Firefox tab takes up ~2.5G, Safari tab takes up ~6G memory, and Chrome tab takes up ~3G. In all cases, the memory is not claimed by GC until I close the tab.

like image 821
SwiftMango Avatar asked Feb 06 '18 18:02

SwiftMango


2 Answers

Different javascript engines use slightly different garbage collection strategies. Node JS uses v8 that is the engine that was initially built for Chrome and Chrome still uses.

To understand more about how garbage collection in V8 works, I suggest this article that is old but still relevant today: https://strongloop.com/strongblog/node-js-performance-garbage-collection/

You can see what the garbage collector is doing running node with the --trace-gc --log-gc options.

In your code the memory increases a lot more than you expect because:

every time you do res += "X" it creates a whole new string and assigns it to res and the prior one is then eligible for garbage collection

As @jfriend00 wrote in the comments. What can really happen is a little more complicated than that but I do not think we need to go in the details.

I prefer to show you, what we can observe running your code.

I slightly changed it:

const humanize = require('humanize')
setInterval(() => console.log(humanize.filesize(process.memoryUsage().heapUsed)),1000);

setInterval(() => {
    const MAXTIMES = 10000000;

    let a = ( ()=> {
        let res = "";
        console.log('starting');
        for(let i=0; i<MAXTIMES; i++){
            // Add this for last run
            // if (i % (MAXTIMES / 10) === 0) {
            //   console.log(i);
            // }
            res = res + "X";
        }
        console.log('done');
        return res;
    })();
}, 5000);

The differences are: 1) humanize helps to format the memory value. 2) I just print heapUsed. 3) I call the function that concatenate strings every 5 sec with setInterval.

When I run it, I get:

$ node index.js
4.36 MB
4.39 MB
4.40 MB
4.40 MB
starting
done
385.80 MB
385.80 MB
385.80 MB
385.80 MB
385.80 MB
starting
done
385.52 MB
4.00 MB
4.00 MB
4.00 MB
4.01 MB
starting
done
385.63 MB
385.63 MB
385.64 MB
385.64 MB
385.64 MB
starting
done
385.77 MB
385.77 MB
385.77 MB
385.78 MB
385.78 MB
starting
done
385.54 MB
...

So, the memory is just 4Mb until the function is called. "starting" and "done" are always printed one after the other since they are synchronous. After the first call the heapUsed gets to 385.80Mb.

After 5 seconds when the function is called again the memory goes to 385.52 MB. Notice that the memory does NOT double. You can instead see that in this second run the memory gets to 4.00 MB after 2 seconds. After that when the function is called again the memory goes again around 385Mb.

--max-old-space-size limits the maximum memory that node can use. If I run the program again limiting the memory to 400MB the output is different:

$ node --max-old-space-size=400 index.js
4.36 MB
4.39 MB
4.40 MB
4.40 MB
starting
done
385.52 MB
384.04 MB
4.00 MB
4.00 MB
4.00 MB
starting
done
385.48 MB
4.00 MB
4.00 MB
4.00 MB
4.01 MB
starting
done
386.11 MB
384.21 MB
4.00 MB
4.00 MB
4.00 MB
starting
done
385.56 MB
4.00 MB

You can see that immediately after the function is called the memory is around 385Mb but it gets quickly to 4.00 MB.

This is because the constrain on memory makes the garbage collection algorithm more "aggressive" in reclaiming memory in order to prevent out of memory errors.

To see what V8 is really doing, we can use the --trace-gc --log-gc parameters. I also added if (i % (MAXTIMES / 10) === 0) console.log(i); in the loop to make sure it is clear when things are happening.

$ node --trace-gc --log-gc --max-old-space-size=400  index.js
[10826:0x103000000]       51 ms: Scavenge 3.4 (6.4) -> 3.2 (7.4) MB, 1.3 / 0.0 ms  allocation failure
[10826:0x103000000]       61 ms: Scavenge 3.5 (7.4) -> 3.5 (8.4) MB, 1.1 / 0.0 ms  allocation failure
4.64 MB
4.67 MB
4.68 MB
4.68 MB
starting
0
[10826:0x103000000]     5094 ms: Scavenge 4.8 (8.9) -> 4.6 (8.9) MB, 1.1 / 0.0 ms  allocation failure
[10826:0x103000000]     5106 ms: Scavenge 5.5 (8.9) -> 5.5 (9.4) MB, 2.8 / 0.0 ms  allocation failure
[10826:0x103000000]     5109 ms: Scavenge 6.1 (9.4) -> 6.1 (10.4) MB, 2.7 / 0.0 ms  allocation failure
[10826:0x103000000]     5112 ms: Scavenge 7.0 (10.4) -> 7.0 (12.4) MB, 2.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5115 ms: Scavenge 7.5 (12.4) -> 7.5 (16.4) MB, 2.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5122 ms: Scavenge 9.9 (16.4) -> 10.0 (16.9) MB, 4.8 / 0.0 ms  allocation failure
[10826:0x103000000]     5127 ms: Scavenge 10.4 (16.9) -> 10.3 (25.4) MB, 5.5 / 0.0 ms  allocation failure
[10826:0x103000000]     5141 ms: Scavenge 15.8 (25.4) -> 16.0 (25.9) MB, 10.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5154 ms: Scavenge 16.2 (25.9) -> 16.0 (43.4) MB, 12.9 / 0.0 ms  allocation failure
[10826:0x103000000]     5182 ms: Scavenge 27.6 (43.4) -> 28.1 (43.9) MB, 21.2 / 0.0 ms  allocation failure
[10826:0x103000000]     5202 ms: Scavenge 28.1 (43.9) -> 27.6 (63.4) MB, 20.2 / 0.0 ms  allocation failure
1000000
[10826:0x103000000]     5234 ms: Scavenge 43.3 (63.4) -> 44.0 (63.9) MB, 24.7 / 0.0 ms  allocation failure
[10826:0x103000000]     5266 ms: Scavenge 44.1 (63.9) -> 43.3 (79.4) MB, 32.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5293 ms: Scavenge 59.1 (79.4) -> 59.8 (79.9) MB, 22.3 / 0.0 ms  allocation failure
[10826:0x103000000]     5323 ms: Scavenge 59.8 (79.9) -> 59.1 (95.4) MB, 30.0 / 0.0 ms  allocation failure
[10826:0x103000000]     5375 ms: Scavenge 74.8 (95.4) -> 75.5 (95.9) MB, 19.9 / 0.0 ms  allocation failure
[10826:0x103000000]     5407 ms: Scavenge 75.5 (95.9) -> 74.8 (111.4) MB, 30.5 / 0.0 ms  allocation failure
2000000
[10826:0x103000000]     5444 ms: Mark-sweep 82.2 (111.4) -> 82.0 (111.4) MB, 8.6 / 0.0 ms  (+ 54.6 ms in 371 steps since start of marking, biggest step 4.0 ms, walltime since start of marking 177 ms) finalize incremental marking via stack guard GC in old space requested
[10826:0x103000000]     5478 ms: Scavenge 90.3 (111.4) -> 90.7 (118.9) MB, 31.9 / 0.0 ms  allocation failure
[10826:0x103000000]     5505 ms: Scavenge 97.7 (118.9) -> 97.7 (127.4) MB, 25.2 / 0.0 ms  allocation failure
[10826:0x103000000]     5534 ms: Scavenge 106.0 (127.4) -> 106.1 (134.9) MB, 26.6 / 0.0 ms  allocation failure
[10826:0x103000000]     5562 ms: Scavenge 113.1 (134.9) -> 113.0 (143.4) MB, 25.7 / 0.0 ms  allocation failure
3000000
[10826:0x103000000]     5589 ms: Scavenge 121.4 (143.4) -> 121.5 (149.4) MB, 23.8 / 0.0 ms  allocation failure
[10826:0x103000000]     5626 ms: Scavenge 128.4 (149.4) -> 128.4 (158.4) MB, 35.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5656 ms: Scavenge 136.8 (158.4) -> 136.9 (165.4) MB, 27.3 / 0.0 ms  allocation failure
[10826:0x103000000]     5699 ms: Scavenge 143.8 (165.4) -> 143.7 (173.9) MB, 26.4 / 0.0 ms  allocation failure
[10826:0x103000000]     5762 ms: Scavenge 152.3 (173.9) -> 152.3 (180.9) MB, 25.3 / 0.0 ms  allocation failure
4000000
[10826:0x103000000]     5829 ms: Scavenge 159.1 (180.9) -> 159.0 (189.4) MB, 26.8 / 0.0 ms  allocation failure
[10826:0x103000000]     5854 ms: Mark-sweep 161.0 (189.4) -> 160.7 (196.9) MB, 3.6 / 0.0 ms  (+ 108.5 ms in 387 steps since start of marking, biggest step 4.4 ms, walltime since start of marking 228 ms) finalize incremental marking via stack guard GC in old space requested
[10826:0x103000000]     5891 ms: Scavenge 174.4 (196.9) -> 175.1 (198.9) MB, 32.0 / 0.0 ms  allocation failure
[10826:0x103000000]     5923 ms: Scavenge 176.4 (198.9) -> 175.8 (212.9) MB, 31.6 / 0.0 ms  allocation failure
[10826:0x103000000]     5946 ms: Scavenge 190.1 (212.9) -> 190.8 (214.4) MB, 18.6 / 0.0 ms  allocation failure
[10826:0x103000000]     5976 ms: Scavenge 191.5 (214.4) -> 190.8 (229.4) MB, 29.8 / 0.0 ms  allocation failure
5000000
[10826:0x103000000]     6002 ms: Scavenge 205.8 (229.4) -> 206.5 (229.4) MB, 19.4 / 0.0 ms  allocation failure
[10826:0x103000000]     6034 ms: Scavenge 206.5 (229.4) -> 205.8 (244.4) MB, 31.7 / 0.0 ms  allocation failure
[10826:0x103000000]     6059 ms: Scavenge 221.5 (244.4) -> 222.2 (244.9) MB, 20.9 / 0.0 ms  allocation failure
[10826:0x103000000]     6088 ms: Scavenge 222.3 (244.9) -> 221.5 (260.4) MB, 28.4 / 0.0 ms  allocation failure
6000000
[10826:0x103000000]     6114 ms: Scavenge 237.3 (260.4) -> 238.0 (260.9) MB, 22.3 / 0.0 ms  allocation failure
[10826:0x103000000]     6142 ms: Scavenge 238.0 (260.9) -> 237.3 (276.4) MB, 27.5 / 0.0 ms  allocation failure
[10826:0x103000000]     6169 ms: Scavenge 253.0 (276.4) -> 253.7 (276.9) MB, 22.4 / 0.0 ms  allocation failure
[10826:0x103000000]     6203 ms: Scavenge 253.7 (276.9) -> 253.0 (292.4) MB, 33.6 / 0.0 ms  allocation failure
[10826:0x103000000]     6380 ms: Scavenge 268.7 (292.4) -> 269.4 (292.9) MB, 20.6 / 0.0 ms  allocation failure
[10826:0x103000000]     6414 ms: Scavenge 269.5 (292.9) -> 268.7 (308.4) MB, 32.1 / 0.0 ms  allocation failure
[10826:0x103000000]     6446 ms: Mark-sweep 269.9 (308.4) -> 269.9 (308.4) MB, 2.1 / 0.0 ms  (+ 183.4 ms in 270 steps since start of marking, biggest step 5.5 ms, walltime since start of marking 304 ms) finalize incremental marking via stack guard GC in old space requested
7000000
[10826:0x103000000]     6478 ms: Scavenge 284.5 (308.4) -> 285.2 (309.9) MB, 25.2 / 0.0 ms  allocation failure
[10826:0x103000000]     6510 ms: Scavenge 285.6 (309.9) -> 284.9 (324.9) MB, 32.4 / 0.0 ms  allocation failure
[10826:0x103000000]     6538 ms: Scavenge 300.2 (324.9) -> 300.9 (325.9) MB, 22.8 / 0.0 ms  allocation failure
[10826:0x103000000]     6570 ms: Scavenge 300.9 (325.9) -> 300.2 (341.4) MB, 31.8 / 0.0 ms  allocation failure
8000000
[10826:0x103000000]     6595 ms: Scavenge 315.9 (341.4) -> 316.7 (342.4) MB, 20.6 / 0.0 ms  allocation failure
[10826:0x103000000]     6643 ms: Scavenge 316.7 (342.4) -> 316.0 (357.9) MB, 48.2 / 0.0 ms  allocation failure
[10826:0x103000000]     6670 ms: Scavenge 331.7 (357.9) -> 332.4 (358.9) MB, 21.9 / 0.0 ms  allocation failure
[10826:0x103000000]     6703 ms: Scavenge 332.4 (358.9) -> 331.7 (374.4) MB, 32.4 / 0.0 ms  allocation failure
[10826:0x103000000]     6728 ms: Scavenge 347.4 (374.4) -> 348.1 (375.4) MB, 20.7 / 0.0 ms  allocation failure
[10826:0x103000000]     6756 ms: Scavenge 348.1 (375.4) -> 347.4 (390.9) MB, 27.9 / 0.0 ms  allocation failure
9000000
[10826:0x103000000]     6986 ms: Mark-sweep 350.9 (390.9) -> 350.8 (390.9) MB, 2.3 / 0.0 ms  (+ 225.8 ms in 55 steps since start of marking, biggest step 6.0 ms, walltime since start of marking 230 ms) finalize incremental marking via stack guard GC in old space requested
[10826:0x103000000]     7020 ms: Scavenge 363.1 (390.9) -> 363.7 (392.4) MB, 30.2 / 0.0 ms  allocation failure
[10826:0x103000000]     7055 ms: Scavenge 366.6 (392.4) -> 366.1 (404.9) MB, 33.7 / 0.0 ms  allocation failure
[10826:0x103000000]     7080 ms: Scavenge 378.9 (404.9) -> 379.3 (407.9) MB, 21.7 / 0.0 ms  allocation failure
[10826:0x103000000]     7106 ms: Scavenge 381.7 (407.9) -> 381.2 (420.9) MB, 25.2 / 0.0 ms  allocation failure
[10826:0x103000000]     7342 ms: Mark-sweep 384.8 (420.9) -> 384.7 (422.9) MB, 3.3 / 0.0 ms  (+ 231.9 ms in 58 steps since start of marking, biggest step 5.5 ms, walltime since start of marking 237 ms) finalize incremental marking via stack guard GC in old space requested
done
385.70 MB
[10826:0x103000000]     7384 ms: Mark-sweep 385.7 (422.9) -> 4.2 (40.9) MB, 39.4 / 0.0 ms  (+ 0.0 ms in 1 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 39 ms) finalize incremental marking via task GC in old space requested
4.22 MB
4.23 MB
4.23 MB
4.23 MB
starting
0
[10826:0x103000000]    12380 ms: Scavenge 20.0 (40.9) -> 20.7 (40.9) MB, 19.4 / 0.0 ms  allocation failure
[10826:0x103000000]    12406 ms: Scavenge 20.7 (40.9) -> 20.0 (55.4) MB, 26.7 / 0.0 ms  allocation failure
[10826:0x103000000]    12430 ms: Scavenge 35.7 (55.4) -> 36.4 (55.9) MB, 19.5 / 0.0 ms  allocation failure
[10826:0x103000000]    12457 ms: Scavenge 36.4 (55.9) -> 35.7 (71.4) MB, 27.3 / 0.0 ms  allocation failure
1000000
[10826:0x103000000]    12484 ms: Scavenge 51.4 (71.4) -> 52.1 (71.9) MB, 22.6 / 0.0 ms  allocation failure
[10826:0x103000000]    12513 ms: Scavenge 52.2 (71.9) -> 51.4 (87.4) MB, 28.2 / 0.0 ms  allocation failure
[10826:0x103000000]    12551 ms: Scavenge 67.2 (87.4) -> 67.9 (87.9) MB, 21.9 / 0.0 ms  allocation failure
[10826:0x103000000]    12578 ms: Scavenge 67.9 (87.9) -> 67.2 (103.4) MB, 26.9 / 0.0 ms  allocation failure
2000000
[10826:0x103000000]    12646 ms: Mark-sweep 81.7 (103.4) -> 81.7 (103.4) MB, 30.1 / 0.0 ms  (+ 46.7 ms in 311 steps since start of marking, biggest step 5.2 ms, walltime since start of marking 189 ms) finalize incremental marking via stack guard GC in old space requested
[10826:0x103000000]    12680 ms: Scavenge 82.9 (103.4) -> 82.9 (118.4) MB, 31.8 / 0.0 ms  allocation failure
[10826:0x103000000]    12712 ms: Scavenge 97.5 (118.4) -> 98.1 (119.9) MB, 20.8 / 0.0 ms  allocation failure
[10826:0x103000000]    12738 ms: Scavenge 98.6 (119.9) -> 98.0 (134.9) MB, 26.8 / 0.0 ms  allocation failure
[10826:0x103000000]    12762 ms: Scavenge 113.1 (134.9) -> 113.8 (135.9) MB, 20.1 / 0.0 ms  allocation failure
[10826:0x103000000]    12789 ms: Scavenge 113.9 (135.9) -> 113.1 (151.4) MB, 26.8 / 0.0 ms  allocation failure
3000000
[10826:0x103000000]    12813 ms: Scavenge 128.9 (151.4) -> 129.6 (151.9) MB, 20.6 / 0.0 ms  allocation failure
[10826:0x103000000]    12839 ms: Scavenge 129.6 (151.9) -> 128.9 (166.4) MB, 25.4 / 0.0 ms  allocation failure
[10826:0x103000000]    12913 ms: Scavenge 144.6 (166.4) -> 145.3 (166.9) MB, 20.9 / 0.0 ms  allocation failure
[10826:0x103000000]    12944 ms: Scavenge 145.3 (166.9) -> 144.6 (182.4) MB, 29.2 / 0.0 ms  allocation failure
[10826:0x103000000]    12997 ms: Mark-sweep 151.5 (182.4) -> 151.5 (182.4) MB, 3.9 / 0.0 ms  (+ 98.2 ms in 363 steps since start of marking, biggest step 5.0 ms, walltime since start of marking 208 ms) finalize incremental marking via stack guard GC in old space requested
4000000
[10826:0x103000000]    13028 ms: Scavenge 160.3 (182.4) -> 160.8 (189.4) MB, 28.7 / 0.0 ms  allocation failure
[10826:0x103000000]    13054 ms: Scavenge 167.3 (189.4) -> 167.2 (198.4) MB, 24.2 / 0.0 ms  allocation failure
[10826:0x103000000]    13079 ms: Scavenge 176.1 (198.4) -> 176.2 (205.4) MB, 22.3 / 0.0 ms  allocation failure
[10826:0x103000000]    13104 ms: Scavenge 182.6 (205.4) -> 182.4 (214.9) MB, 23.8 / 0.0 ms  allocation failure
[10826:0x103000000]    13129 ms: Scavenge 191.5 (214.9) -> 191.6 (221.4) MB, 23.1 / 0.0 ms  allocation failure
5000000
[10826:0x103000000]    13155 ms: Scavenge 197.9 (221.4) -> 197.7 (230.9) MB, 24.9 / 0.0 ms  allocation failure
[10826:0x103000000]    13181 ms: Scavenge 206.9 (230.9) -> 207.1 (237.4) MB, 24.0 / 0.0 ms  allocation failure
[10826:0x103000000]    13206 ms: Scavenge 213.2 (237.4) -> 213.0 (246.9) MB, 23.2 / 0.0 ms  allocation failure
[10826:0x103000000]    13232 ms: Scavenge 222.4 (246.9) -> 222.5 (253.4) MB, 23.0 / 0.0 ms  allocation failure
[10826:0x103000000]    13258 ms: Scavenge 228.5 (253.4) -> 228.3 (262.9) MB, 24.9 / 0.0 ms  allocation failure
6000000
[10826:0x103000000]    13316 ms: Scavenge 237.8 (262.9) -> 238.0 (267.9) MB, 24.6 / 0.0 ms  allocation failure
[10826:0x103000000]    13381 ms: Scavenge 243.8 (267.9) -> 243.6 (277.9) MB, 25.9 / 0.0 ms  allocation failure
[10826:0x103000000]    13480 ms: Mark-sweep 251.5 (277.9) -> 251.2 (282.9) MB, 5.3 / 0.0 ms  (+ 159.5 ms in 371 steps since start of marking, biggest step 4.1 ms, walltime since start of marking 248 ms) finalize incremental marking via stack guard GC in old space requested
[10826:0x103000000]    13517 ms: Scavenge 259.1 (282.9) -> 259.4 (290.4) MB, 34.7 / 0.0 ms  allocation failure
[10826:0x103000000]    13545 ms: Scavenge 266.9 (290.4) -> 266.9 (298.4) MB, 23.6 / 0.0 ms  allocation failure
7000000
[10826:0x103000000]    13571 ms: Scavenge 274.8 (298.4) -> 274.8 (306.4) MB, 24.2 / 0.0 ms  allocation failure
[10826:0x103000000]    13597 ms: Scavenge 282.3 (306.4) -> 282.3 (313.9) MB, 24.2 / 0.0 ms  allocation failure
[10826:0x103000000]    13636 ms: Scavenge 290.1 (313.9) -> 290.1 (321.9) MB, 36.8 / 0.0 ms  allocation failure
[10826:0x103000000]    13662 ms: Scavenge 297.7 (321.9) -> 297.7 (329.9) MB, 24.3 / 0.0 ms  allocation failure
[10826:0x103000000]    13687 ms: Scavenge 305.5 (329.9) -> 305.5 (337.4) MB, 23.7 / 0.0 ms  allocation failure
8000000
[10826:0x103000000]    13717 ms: Scavenge 313.0 (337.4) -> 313.0 (345.4) MB, 27.6 / 0.0 ms  allocation failure
[10826:0x103000000]    13746 ms: Scavenge 320.9 (345.4) -> 320.9 (352.9) MB, 25.9 / 0.0 ms  allocation failure
[10826:0x103000000]    13773 ms: Scavenge 328.4 (352.9) -> 328.4 (360.9) MB, 24.9 / 0.0 ms  allocation failure
[10826:0x103000000]    13798 ms: Scavenge 336.2 (360.9) -> 336.2 (368.9) MB, 23.5 / 0.0 ms  allocation failure
[10826:0x103000000]    14033 ms: Mark-sweep 339.4 (368.9) -> 339.0 (376.9) MB, 4.0 / 0.0 ms  (+ 229.2 ms in 50 steps since start of marking, biggest step 5.7 ms, walltime since start of marking 234 ms) finalize incremental marking via stack guard GC in old space requested
9000000
[10826:0x103000000]    14072 ms: Scavenge 351.6 (376.9) -> 352.2 (379.9) MB, 35.7 / 0.0 ms  allocation failure
[10826:0x103000000]    14101 ms: Scavenge 354.7 (379.9) -> 354.3 (392.9) MB, 28.0 / 0.0 ms  allocation failure
[10826:0x103000000]    14125 ms: Scavenge 367.3 (392.9) -> 367.8 (395.9) MB, 21.4 / 0.0 ms  allocation failure
[10826:0x103000000]    14154 ms: Scavenge 369.9 (395.9) -> 369.3 (409.4) MB, 28.1 / 0.0 ms  allocation failure
[10826:0x103000000]    14178 ms: Scavenge 383.0 (409.4) -> 383.5 (411.9) MB, 20.5 / 0.0 ms  allocation failure
[10826:0x103000000]    14311 ms: Scavenge 385.0 (411.9) -> 384.4 (425.4) MB, 30.4 / 0.0 ms  allocation failure
done
385.77 MB
[10826:0x103000000]    14455 ms: Mark-sweep 385.8 (425.4) -> 382.9 (425.4) MB, 1.2 / 0.0 ms  (+ 244.2 ms in 103 steps since start of marking, biggest step 6.2 ms, walltime since start of marking 278 ms) finalize incremental marking via task GC in old space requested
382.93 MB
[10826:0x103000000]    15413 ms: Mark-sweep 382.9 (425.4) -> 4.2 (41.9) MB, 0.8 / 0.0 ms  (+ 2.8 ms in 4 steps since start of marking, biggest step 1.1 ms, walltime since start of marking 4 ms) finalize incremental marking via task GC in old space requested
4.22 MB
4.23 MB

The scavenge cycles do not really reclaim any memory in this case and we have to wait for the full mark-sweep to finish in order to free all the memory.

Does it makes sense?

In conclusion, I would like to add that:

  1. Real code does not usually have 10 million string concatenations in one tick.
  2. V8's garbage collection algorithm usually does the right thing in order to strike the right balance between preventing the process to run out of memory and preventing itself to unnecessarily slow down the process.
  3. In case you have a problem with garbage collection you need to do some profiling and the solution usually implies refactoring the code to do less work in one tick. It can be a lot more complicated but getting into that is probably not relevant for this question.
like image 192
Chris Cinelli Avatar answered Oct 01 '22 19:10

Chris Cinelli


MDN web docs has detailed 2 types of JavaScript Garbage Collection algorithms.

  1. Reference-counting algorithm
  2. Mark-and-sweep algorithm

What you are referring is the first one, Reference-counting algorithm, which clears the objects when that variables have no other references pointing towards them. So when a function returns all inaccessible objects are cleared and memory is freed.

Reference-counting algorithm cannot clear objects that are no longer needed, if they have references to each other creating a reference cycle. Even if an object has reference to itself but no other references to it, is never freed because it has a reference and these orphaned objects persists in the memory. Only IE6 and IE7 implements this garbage collection algorithm.

All modern browsers ship a garbage-collector which uses Mark-and-sweep algorithm, that sweeps the entire memory at a specific interval or when it deems it necessary to free up all unused memory allocations. From MDN web docs:

This algorithm assumes the knowledge of a set of objects called roots (In JavaScript, the root is the global object). Periodically, the garbage-collector will start from these roots, find all objects that are referenced from these roots, then all objects referenced from these, etc. Starting from the roots, the garbage collector will thus find all reachable objects and collect all non-reachable objects.

That's why you see the memory usage does not go down when the function returns immediately, the Mark-and-sweep garbage collector does not act after every function return, it rather acts at specific intervals periodically. So you see memory usage go high when the loop is executed and function returns, but it stays high, until the GC kicks into action and clears the rubbish and the memory usage goes down.

like image 39
Munim Munna Avatar answered Oct 01 '22 21:10

Munim Munna