Node: Memory growth issue about crypto module.

[gentlejo]

• Version: v6.9.4 & v8.1.2
• Platform: Linux 3.10.0-514.21.2.el7.x86_64 #1 SMP Tue Jun 20 12:24:47 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

If I run cipher related function many times, I can see memory growth even though execute gc manually.
To be more specific, if I use cipher.final(), it causes memory growth.

Below is test code.

    var crypto = require('crypto');

    function testCipher() {
        var cipher = crypto.createCipheriv('aes-128-gcm', Buffer.from('1234567890123456'), Buffer.from('a1'));
        cipher.setAutoPadding(false);

        return Buffer.concat([cipher.update(Buffer.from('datas')), cipher.final()]);
    }

    for (var i = 0; i < 100000000; i++) {
        testCipher();

        if (i % 200000 === 0) {
            gc(true);
        }
    } 

[bnoordhuis]

Define 'memory growth'? How and what do you measure?

[gentlejo]

@bnoordhuis I mean memory leak. I just run that code and the result was like attached picture.

[bnoordhuis]

Okay, but what is 'Memory used'? RSS, JS heap, something else?

It's not unexpected that the memory footprint grows over time because the garbage collector periodically resizes the heap. As long as you don't get actual out-of-memory errors, there probably is no memory leak.

[gentlejo]

@bnoordhuis I took memwatch result of heap diff and rss. I executed 5,000,000 times in a loop. If this is not a memory leak, why memory usage is growing? My test approach was wrong?

{ rss: 37056512, heapTotal: 11571200, heapUsed: 4408232 }
{ rss: 49192960, heapTotal: 11571200, heapUsed: 6554064 }
{ rss: 55951360, heapTotal: 11571200, heapUsed: 6415776 }
{ rss: 62709760, heapTotal: 11571200, heapUsed: 6414200 }
{ rss: 69468160, heapTotal: 11571200, heapUsed: 6414432 }
{ rss: 76226560, heapTotal: 11571200, heapUsed: 6414888 }
{ rss: 82984960, heapTotal: 11571200, heapUsed: 6414896 }
{ rss: 89743360, heapTotal: 11571200, heapUsed: 6415128 }
{ rss: 96501760, heapTotal: 11571200, heapUsed: 6415360 }
{ rss: 103260160, heapTotal: 11571200, heapUsed: 6415592 }
{ rss: 110018560, heapTotal: 11571200, heapUsed: 6416056 }
{ rss: 116776960, heapTotal: 11571200, heapUsed: 6416072 }
{ rss: 123265024, heapTotal: 11571200, heapUsed: 6416312 }
{ rss: 130023424, heapTotal: 11571200, heapUsed: 6416552 }
{ rss: 136781824, heapTotal: 11571200, heapUsed: 6416792 }
{ rss: 149487616, heapTotal: 15765504, heapUsed: 8477160 }
{ rss: 156246016, heapTotal: 15765504, heapUsed: 6402440 }
{ rss: 163004416, heapTotal: 15765504, heapUsed: 6403656 }
{ rss: 169762816, heapTotal: 15765504, heapUsed: 6404240 }
{ rss: 176521216, heapTotal: 15765504, heapUsed: 6404480 }
{ rss: 183279616, heapTotal: 15765504, heapUsed: 6403936 }
{ rss: 190038016, heapTotal: 15765504, heapUsed: 6403984 }

...
...

{ before: { nodes: 24112, size_bytes: 3860344, size: '3.68 mb' },
  after: { nodes: 28290, size_bytes: 4350640, size: '4.15 mb' },
  change:
   { size_bytes: 490296,
     size: '478.8 kb',
     freed_nodes: 925,
     allocated_nodes: 5103,
     details:
      [ { what: 'Array',
  size_bytes: 240992,
  size: '235.34 kb',
  '+': 1786,
  '-': 345 }
{ what: 'ArrayBuffer',
  size_bytes: 0,
  size: '0 bytes',
  '+': 1,
  '-': 1 }
{ what: 'Buffer',
  size_bytes: -80,
  size: '-80 bytes',
  '+': 1,
  '-': 1 }
{ what: 'BufferList',
  size_bytes: 224,
  size: '224 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Closure',
  size_bytes: 15120,
  size: '14.77 kb',
  '+': 211,
  '-': 0 }
{ what: 'Code',
  size_bytes: 80384,
  size: '78.5 kb',
  '+': 550,
  '-': 161 }
{ what: 'Console',
  size_bytes: 96,
  size: '96 bytes',
  '+': 1,
  '-': 0 }
{ what: 'CorkedRequest',
  size_bytes: 224,
  size: '224 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Duplex',
  size_bytes: 56,
  size: '56 bytes',
  '+': 1,
  '-': 0 }
{ what: 'EventEmitter',
  size_bytes: 56,
  size: '56 bytes',
  '+': 1,
  '-': 0 }
{ what: 'EventHandlers',
  size_bytes: 208,
  size: '208 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Map', size_bytes: 32, size: '32 bytes', '+': 1, '-': 0 }
{ what: 'Native',
  size_bytes: 1168,
  size: '1.14 kb',
  '+': 4,
  '-': 1 }
{ what: 'NativeModule',
  size_bytes: 256,
  size: '256 bytes',
  '+': 4,
  '-': 0 }
{ what: 'Number',
  size_bytes: 32,
  size: '32 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Object',
  size_bytes: 18416,
  size: '17.98 kb',
  '+': 372,
  '-': 0 }
{ what: 'ReadableState',
  size_bytes: 576,
  size: '576 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Signal',
  size_bytes: 64,
  size: '64 bytes',
  '+': 2,
  '-': 0 }
{ what: 'Socket',
  size_bytes: 112,
  size: '112 bytes',
  '+': 2,
  '-': 0 }
{ what: 'String',
  size_bytes: 56136,
  size: '54.82 kb',
  '+': 334,
  '-': 82 }
{ what: 'TTY', size_bytes: 96, size: '96 bytes', '+': 3, '-': 0 }
{ what: 'WritableState',
  size_bytes: 576,
  size: '576 bytes',
  '+': 2,
  '-': 0 }
{ what: 'WriteStream',
  size_bytes: 208,
  size: '208 bytes',
  '+': 2,
  '-': 0 }
{ what: 'WriteWrap',
  size_bytes: 32,
  size: '32 bytes',
  '+': 1,
  '-': 0 }
{ what: 'system / Context',
  size_bytes: 1312,
  size: '1.28 kb',
  '+': 13,
  '-': 0 } ] } }

[bnoordhuis]

Now we're getting somewhere. So it's RSS that steadily grows while the JS heap only grows in fits. At what interval did you record those samples?

Since you are on Linux, can you check if your issue is #11077? In a nutshell: disable transparent huge pages if they are enabled.

[gentlejo]

I recorded every 200,000 executions. I will check the link you mentioned.

@bnoordhuis Already turned off.
[gentlejo@server ~]$ cat /sys/kernel/mm/transparent_hugepage/enabled
always madvise [never]

[gentlejo]

RSS is only increasing when I called cipher.final() method. If I don't call cipher.final() method, RSS is not increasing. Can I free or prevent RSS increasing?

[bnoordhuis]

Thanks, I was able to reproduce, I'll look into it.

[schmod]

Do we know if this is a regression, and if so, when it was introduced?

[bnoordhuis]

Not a regression, AFAICT. It's been present ever since authenticated mode support was added in commit e0d31ea from November 2013.

[gabrielcsapo]

@bnoordhuis how can this be prevented?