NodeJS CPU heavy tick and memory leak debugging

Once upon a time…

The Memory usage goes too high

It fills the instance memory every few hours

and been killed by the OS scheduler

Symptom

the response time becomes higher and higher, until the memory usage reaches 100% or above
and the application stops responding
there is not enough swap left, the server can even fail to accept SSH connections

This problem is the well-known "Memory leaks"

We need to find out who's the killer

again

What tools we have

inspector
memwatch-next & heapdump

Enable the inspector

use the built-in inspector to understand your app

node --inspect app.js

Use ApacheBench to make some load

ab -k -c 20 -n 250 "http://localhost:3000"

20 concurrent connections with 250 requests per each

There is no graphic server on the production

Let's make the server generates the memory dump

memwatch-next

triggers events when the memory usage still growing after 5 consecutive GCs

 const Memwatch = require('memwatch-next');
/**
 * Check for memory leaks
 */
let hd = null;
Memwatch.on('leak', (info) => {
  console.log('memwatch::leak');
  console.error(info);
  if (!hd) {
    hd = new Memwatch.HeapDiff();
 }
 else {
   const diff = hd.end();
   console.error(Util.inspect(diff, true, null));
   trace.report('memwatch::leak', {
     HeapDiff: hd
   });
   hd = null;
 }
});
 
Memwatch.on('stats', (stats) => {
  console.log('memwatch::stats');
  console.error(Util.inspect(stats, true, null));
  trace.report('memwatch::stats', {
    Stats: stats
 });
});

View the heapdiff

memwatch::stats           // <-- GC stats

{ num_full_gc: 227,
num_inc_gc: 991,
heap_compactions: 227,

usage_trend: 1.3,         // <-- the usage trending

estimated_base: 49219293,
current_base: 47057208,
min: 41628720,
max: 50299360 }

memwatch::leak            // <-- the leak event

growth=1362440, reason=heap growth over 5 consecutive GCs (1m 56s) - 40.32 mb/hr

// show the heap diff

{ before: { nodes: 401400, size_bytes: 44743648, size: '42.67 mb' },
after: { nodes: 407650, size_bytes: 46306635, size: '44.16 mb' },
change:
{ size_bytes: 1562987,
size: '1.49 mb',
freed_nodes: 24397,
allocated_nodes: 30647,
details:
[ { what: 'Array',
size_bytes: 557728,
size: '544.66 kb',
'+': 5438,
'-': 2962 },
{ what: 'ArrayBuffer',
size_bytes: 560,
size: '560 bytes',
'+': 21,
'-': 14 },
{ what: 'Buffer',
size_bytes: 400,
size: '400 bytes',
'+': 12,
'-': 7 },
{ what: 'BufferList',
size_bytes: 1200,
size: '1.17 kb',
'+': 48,
'-': 23 },
{ what: 'Client', size_bytes: 0, size: '0 bytes', '+': 5, '-': 5 },
{ what: 'Closure',
size_bytes: 28080,
size: '27.42 kb',
'+': 1525,
'-': 1021 },
{ what: 'Code',
size_bytes: 405144,
size: '395.65 kb',
'+': 315,
'-': 61 },
...

It's better if we can have the whole heap to inspect

heapdump

dumping the memory stack of node.js app to a file to inspect later

 const http = require('http');
const heapdump = require('heapdump');
 
const requestLogs = [];
const server = http.createServer((req, res) => {
    if (req.url === '/heapdump') {
        heapdump.writeSnapshot((err, filename) => {
            console.log('Heap dump written to', filename)
        });
    }
    requestLogs.push({ url: req.url, date: new Date() });
    res.end(JSON.stringify(requestLogs));
});
 
server.listen(3000);
console.log('Server listening to port 3000. Press Ctrl+C to stop it.');
console.log(`Heapdump enabled. Run "kill -USR2 ${process.pid}" or send a request to "/heapdump" to generate a heapdump.`);

Trigger dumping by USR2 signal

 $ node index.js
Server listening to port 3000. Press Ctrl+C to stop it.
Heapdump enabled. Run "kill -USR2 29431" or send a request to "/heapdump" to generate a heapdump.
 
$ kill -USR2 29431
$ curl http://localhost:3000/heapdump
$ ls
heapdump-31208326.300922.heapsnapshot
heapdump-31216569.978846.heapsnapshot

Load dump to Chrome Dev Tools

Look into the dev tools

Here you are!

We found the gray-matter library that used for generating the page title cause the problem.

ref.

	const Memwatch = require('memwatch-next');
	/**
	* Check for memory leaks
	*/
	let hd = null;
	Memwatch.on('leak', (info) => {
	console.log('memwatch::leak');
	console.error(info);
	if (!hd) {
	hd = new Memwatch.HeapDiff();
	}
	else {
	const diff = hd.end();
	console.error(Util.inspect(diff, true, null));
	trace.report('memwatch::leak', {
	HeapDiff: hd
	});
	hd = null;
	}
	});

	Memwatch.on('stats', (stats) => {
	console.log('memwatch::stats');
	console.error(Util.inspect(stats, true, null));
	trace.report('memwatch::stats', {
	Stats: stats
	});
	});

	const http = require('http');
	const heapdump = require('heapdump');

	const requestLogs = [];
	const server = http.createServer((req, res) => {
	if (req.url === '/heapdump') {
	heapdump.writeSnapshot((err, filename) => {
	console.log('Heap dump written to', filename)
	});
	}
	requestLogs.push({ url: req.url, date: new Date() });
	res.end(JSON.stringify(requestLogs));
	});

	server.listen(3000);
	console.log('Server listening to port 3000. Press Ctrl+C to stop it.');
	console.log(`Heapdump enabled. Run "kill -USR2 ${process.pid}" or send a request to "/heapdump" to generate a heapdump.`);

	$ node index.js
	Server listening to port 3000. Press Ctrl+C to stop it.
	Heapdump enabled. Run "kill -USR2 29431" or send a request to "/heapdump" to generate a heapdump.

	$ kill -USR2 29431
	$ curl http://localhost:3000/heapdump
	$ ls
	heapdump-31208326.300922.heapsnapshot
	heapdump-31216569.978846.heapsnapshot