GC not works as expected with crypto module

[clowwindy]

node -e 'console.log(process.arch, process.platform, process.versions)'
x64 darwin { http_parser: '1.0',
  node: '0.10.15',
  v8: '3.14.5.9',
  ares: '1.9.0-DEV',
  uv: '0.10.13',
  zlib: '1.2.3',
  modules: '11',
  openssl: '1.0.1e' }

Here's a simple program that encrypts 16MB data 100 times:

var crypto = require('crypto');

var data = new Buffer(1024 * 1024 * 16);
for (var i = 0; i < 100; i++) {
    (function() {
        var cipher = crypto.createCipher('AES-256-CFB', 'my_password');
        cipher.update(data);
        cipher.final();
        cipher = null;
        console.log(i, process.memoryUsage());
    })();
}
data = null;

console.log('done!');

// wait and see if memory footprint reduces
setInterval(function() {
    console.log(process.memoryUsage());
}, 1000);

And we can see the gabage collector not work as expected. RSS went up to 300MB, after the encryption it never went down.

$ node --trace_gc lib/shadowsocks/memory.js
[51299]      465 ms: Mark-sweep 2.0 (36.0) -> 1.7 (38.0) MB, 3 / 8 ms [allocation failure] [GC in old space requested].
0 { rss: 64339968, heapTotal: 7195904, heapUsed: 1987336 }
1 { rss: 64729088, heapTotal: 7195904, heapUsed: 2365328 }
2 { rss: 81526784, heapTotal: 7195904, heapUsed: 2389152 }
3 { rss: 98312192, heapTotal: 7195904, heapUsed: 2397136 }
4 { rss: 115097600, heapTotal: 7195904, heapUsed: 2405120 }
5 { rss: 131883008, heapTotal: 7195904, heapUsed: 2413120 }
6 { rss: 148668416, heapTotal: 7195904, heapUsed: 2420976 }
7 { rss: 165453824, heapTotal: 7195904, heapUsed: 2428832 }
8 { rss: 182239232, heapTotal: 7195904, heapUsed: 2436632 }
9 { rss: 199020544, heapTotal: 7195904, heapUsed: 2444432 }
10 { rss: 215805952, heapTotal: 7195904, heapUsed: 2452232 }
11 { rss: 232591360, heapTotal: 7195904, heapUsed: 2460072 }
12 { rss: 249380864, heapTotal: 7195904, heapUsed: 2467912 }
13 { rss: 266166272, heapTotal: 7195904, heapUsed: 2475752 }
14 { rss: 283074560, heapTotal: 7195904, heapUsed: 2488088 }
15 { rss: 299859968, heapTotal: 7195904, heapUsed: 2495928 }
[51299]     6432 ms: Mark-sweep 2.4 (38.0) -> 2.2 (38.0) MB, 49 / 52 ms [external memory allocation limit reached] [GC in old space requested].
16 { rss: 316149760, heapTotal: 7195904, heapUsed: 2305304 }
17 { rss: 316149760, heapTotal: 7195904, heapUsed: 2321376 }
18 { rss: 316153856, heapTotal: 7195904, heapUsed: 2330800 }
19 { rss: 316153856, heapTotal: 7195904, heapUsed: 2338640 }
20 { rss: 316153856, heapTotal: 7195904, heapUsed: 2346440 }
21 { rss: 316153856, heapTotal: 7195904, heapUsed: 2354240 }
22 { rss: 316153856, heapTotal: 7195904, heapUsed: 2362040 }
23 { rss: 316153856, heapTotal: 7195904, heapUsed: 2369840 }
24 { rss: 316166144, heapTotal: 7195904, heapUsed: 2380616 }
25 { rss: 316166144, heapTotal: 7195904, heapUsed: 2388456 }
26 { rss: 316166144, heapTotal: 7195904, heapUsed: 2396256 }
27 { rss: 316178432, heapTotal: 7195904, heapUsed: 2406288 }
28 { rss: 316182528, heapTotal: 7195904, heapUsed: 2414464 }
29 { rss: 316252160, heapTotal: 7195904, heapUsed: 2435024 }
30 { rss: 316252160, heapTotal: 7195904, heapUsed: 2444240 }
31 { rss: 316264448, heapTotal: 7195904, heapUsed: 2462176 }
[51299]    12253 ms: Mark-sweep 2.4 (38.0) -> 2.2 (38.0) MB, 71 / 75 ms [external memory allocation limit reached] [GC in old space requested].
32 { rss: 316264448, heapTotal: 7195904, heapUsed: 2330696 }
33 { rss: 316268544, heapTotal: 7195904, heapUsed: 2349208 }
34 { rss: 316268544, heapTotal: 7195904, heapUsed: 2359784 }
35 { rss: 316268544, heapTotal: 7195904, heapUsed: 2371320 }
36 { rss: 316268544, heapTotal: 7195904, heapUsed: 2379120 }
37 { rss: 316268544, heapTotal: 7195904, heapUsed: 2386920 }
38 { rss: 316272640, heapTotal: 7195904, heapUsed: 2396248 }
39 { rss: 316272640, heapTotal: 7195904, heapUsed: 2404088 }
40 { rss: 316272640, heapTotal: 7195904, heapUsed: 2411888 }
41 { rss: 316272640, heapTotal: 7195904, heapUsed: 2422136 }
42 { rss: 316272640, heapTotal: 7195904, heapUsed: 2429936 }
43 { rss: 316272640, heapTotal: 7195904, heapUsed: 2437736 }
44 { rss: 316309504, heapTotal: 7195904, heapUsed: 2481952 }
45 { rss: 316309504, heapTotal: 7195904, heapUsed: 2491400 }
46 { rss: 316309504, heapTotal: 7195904, heapUsed: 2499200 }
47 { rss: 316309504, heapTotal: 7195904, heapUsed: 2507000 }
[51299]    18312 ms: Mark-sweep 2.4 (38.0) -> 2.3 (38.0) MB, 61 / 65 ms [external memory allocation limit reached] [GC in old space requested].
48 { rss: 316317696, heapTotal: 7195904, heapUsed: 2364000 }
49 { rss: 316317696, heapTotal: 7195904, heapUsed: 2379944 }
50 { rss: 316317696, heapTotal: 7195904, heapUsed: 2388840 }
51 { rss: 316317696, heapTotal: 7195904, heapUsed: 2396640 }
52 { rss: 316317696, heapTotal: 7195904, heapUsed: 2404440 }
53 { rss: 316317696, heapTotal: 7195904, heapUsed: 2412240 }
54 { rss: 316317696, heapTotal: 7195904, heapUsed: 2420040 }
55 { rss: 316317696, heapTotal: 7195904, heapUsed: 2427840 }
56 { rss: 316317696, heapTotal: 7195904, heapUsed: 2435640 }
57 { rss: 316317696, heapTotal: 7195904, heapUsed: 2443440 }
58 { rss: 316317696, heapTotal: 7195904, heapUsed: 2451240 }
59 { rss: 316321792, heapTotal: 7195904, heapUsed: 2459040 }
60 { rss: 316321792, heapTotal: 7195904, heapUsed: 2466880 }
61 { rss: 316321792, heapTotal: 7195904, heapUsed: 2476416 }
62 { rss: 316321792, heapTotal: 7195904, heapUsed: 2484216 }
63 { rss: 316321792, heapTotal: 7195904, heapUsed: 2492016 }
[51299]    24390 ms: Mark-sweep 2.4 (38.0) -> 2.2 (38.0) MB, 64 / 68 ms [external memory allocation limit reached] [GC in old space requested].
64 { rss: 316321792, heapTotal: 7195904, heapUsed: 2340344 }
65 { rss: 316321792, heapTotal: 7195904, heapUsed: 2356288 }
66 { rss: 316346368, heapTotal: 7195904, heapUsed: 2376680 }
67 { rss: 316346368, heapTotal: 7195904, heapUsed: 2384856 }
68 { rss: 316346368, heapTotal: 7195904, heapUsed: 2392656 }
69 { rss: 316346368, heapTotal: 7195904, heapUsed: 2400456 }
70 { rss: 316346368, heapTotal: 7195904, heapUsed: 2408256 }
71 { rss: 316350464, heapTotal: 7195904, heapUsed: 2416056 }
72 { rss: 316350464, heapTotal: 7195904, heapUsed: 2423896 }
73 { rss: 316350464, heapTotal: 7195904, heapUsed: 2431696 }
74 { rss: 316350464, heapTotal: 7195904, heapUsed: 2439496 }
75 { rss: 316489728, heapTotal: 7195904, heapUsed: 2465560 }
76 { rss: 316489728, heapTotal: 7195904, heapUsed: 2473400 }
77 { rss: 316489728, heapTotal: 7195904, heapUsed: 2481200 }
78 { rss: 316489728, heapTotal: 7195904, heapUsed: 2491000 }
79 { rss: 317038592, heapTotal: 7195904, heapUsed: 2540600 }
[51299]    30422 ms: Mark-sweep 2.4 (38.0) -> 2.2 (38.0) MB, 57 / 60 ms [external memory allocation limit reached] [GC in old space requested].
80 { rss: 316416000, heapTotal: 7195904, heapUsed: 2261336 }
81 { rss: 316424192, heapTotal: 7195904, heapUsed: 2290056 }
82 { rss: 316428288, heapTotal: 7195904, heapUsed: 2306256 }
83 { rss: 316428288, heapTotal: 7195904, heapUsed: 2315232 }
84 { rss: 316428288, heapTotal: 7195904, heapUsed: 2323032 }
85 { rss: 316428288, heapTotal: 7195904, heapUsed: 2330832 }
86 { rss: 316428288, heapTotal: 7195904, heapUsed: 2338632 }
87 { rss: 316428288, heapTotal: 7195904, heapUsed: 2346432 }
88 { rss: 316428288, heapTotal: 7195904, heapUsed: 2354232 }
89 { rss: 316428288, heapTotal: 7195904, heapUsed: 2362032 }
90 { rss: 316428288, heapTotal: 7195904, heapUsed: 2369832 }
91 { rss: 316428288, heapTotal: 7195904, heapUsed: 2377632 }
92 { rss: 316428288, heapTotal: 7195904, heapUsed: 2390824 }
93 { rss: 316432384, heapTotal: 7195904, heapUsed: 2398920 }
94 { rss: 316432384, heapTotal: 7195904, heapUsed: 2406760 }
95 { rss: 316432384, heapTotal: 7195904, heapUsed: 2414560 }
[51299]    36286 ms: Mark-sweep 2.3 (38.0) -> 2.1 (38.0) MB, 67 / 69 ms [external memory allocation limit reached] [GC in old space requested].
96 { rss: 316436480, heapTotal: 7195904, heapUsed: 2173216 }
97 { rss: 316448768, heapTotal: 7195904, heapUsed: 2241344 }
98 { rss: 316448768, heapTotal: 7195904, heapUsed: 2261272 }
99 { rss: 316448768, heapTotal: 7195904, heapUsed: 2271000 }
done!
{ rss: 316522496, heapTotal: 7195904, heapUsed: 2359208 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2372640 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2380464 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2387568 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2394672 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2401808 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2408912 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2416016 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2423120 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2430224 }
{ rss: 316526592, heapTotal: 7195904, heapUsed: 2437360 }

I also found that a simple loop of crypto.randomBytes(16 * 1024 * 1024) will lead to the same result.

With --expose-gc supplied, doing gc() manually after each iteration, RSS only takes up to 65MB.

[bnoordhuis]

That's not unexpected. It's an artifact of how buffers and the garbage collector interact.

The V8 GC takes a lazy approach to memory management, it tries to do as little work as possible because garbage collection is expensive.

The flip side of that is that buffers - which are essentially tiny JS objects that point to memory outside of the JS heap - tend to live longer and hold on to that external memory longer than is strictly needed.

It has been addressed to some extent in master but the basic issue will never go away completely. If that's a problem for you, you'll have to invoke the garbage collector manually from time to time.

[meteormatt]

@bnoordhuis 👍

[Bernou]

greate

[zqw]

great!

[supermoonie]

great!