how to debug node.js causing 100% cpu usage?

Question

I have a node app that uses express and redis. On our development server, after a bit of use node starts to use 100% cpu. The application still responds but top reports node using 100%. The cpu doesn't drop until node is restarted.

I have not nailed it down to any particular route or function that is causing it.

What is the best way to diagnose this problem?

I looked at node-inspector with the v8-profiler and it gave me the same error that is reported here https://github.com/dannycoates/v8-profiler/issues/10

Answer 1

You can profile your app with node-tick.

1. Install node-tick by sudo npm -g install tick
2. Run your app with enabled profile node --prof ./app.js
3. After some time with CPU 100% usage stop your app
4. You can see v8.log in your app directory, now you can read it with node-tick-processor
5. Run node-tick-processor and explain the results
6. Load v8.log into chrome://tracing to analyze as a tree.

node js cpu 100%

Answer 2

I found the problem by writing a script to record every request and then replay them.

The problem was caused because I had a callback that was not being returned.

myAsncFunc(function(err, data) {

    if (err) { callback(err) }

    //node kept going after the error was returned to the user.
    // make sure you, return callback(err)

})

Here was my replay.js code for anyone interested.

var request = require('request');
var async = require('async');
var redis = require('redis');


var host = 'http://myhost.com';
var jobs = true;

var client = redis.createClient();

async.whilst(
    function () { return jobs; },
    function (callback) {
        client.lpop('history', function(err, url) {
            console.log(url);
            if (!url) {
                jobs = false;
                callback();
            }
            request.get({url:host+url}, function() {
                callback();
            });
        })
    },
    function (err) {
        console.log('done')
    }
);

And in you're express app.

app.get('/*', function(req, res, next) {
    var url = req.originalUrl;
    redis.rpush('history', url);   
    next();
});

It's cool because every history item that is played will be added again to the queue so it continually loops and every time you visit a new page, it will add that one to the queue.

Answer 3

Constantly running at 100% CPU is typical for infinite loop. This is a real problem in singlethreaded nodejs but unfortunately there is a lack of info on it. Although you state that your server still responds and infinite loop is not your case you still may find usefull hints to debugging live nodejs application.

Eventually I have found the only useful article: How to track the deadloop in nodejs:

Connect to you server via SSH. Identify nodejs process id. Now, let’s tell the process to listen for debugging requests. Yes, we’re using a command called kill. No, we’re not killing the process. We’re sending it a different signal.

kill -SIGUSR1 4702

Once you do this, the process is open to a debugger connection. In fact, it will print a special URL to its console log, and you can open that URL in Chrome to debug the process! But, maybe you don’t want to drill a hole through a firewall and a container configuration just to make that connection. Yeah, me neither. So let’s debug at the command line instead:

node inspect -p 4702

You’ll see this prompt:

debug>

Then type:

pause

And you get back:

break in file:///somewhere/something.js:555
>555         for (prop in inputObject) {
510             if (hasOwnProp(inputObject, prop)) {
511                 normalizedProp = normalizeUnits(prop);

Yes! We have our first hint. The app was executing line 555 in file something.js. That might be enough to see the bug right away. But usually we need more information than that. You can type backtrace to get a complete stack trace:

#0 someFunctionName file:///somewhere/somefile.js:444:22
#1 someFunctionName file:///somewhere/somefile.js:555:33
#2 someFunctionName file:///somewhere/somefile.js:666:44

… And so on.

Answer 4

If you are using UI app with webpack, pay attention on watchOptions or watch. For me, disabling poll solve the problem

watchOptions: {
            poll: false
        }

Or you can set a time, when poll will be triggered like poll: 3000 (once in 3sec) https://webpack.js.org/configuration/watch/#watchoptionsignored

Answer 5

I experienced also 100% CPU usage till i switched off supervisor mode (causing node to restart, when a file changes).

This probably does not answer this question, but in case some novice like me worries about CPU usage, this could be the case.

Answer 6

Update: now working through npx without installation

$ npx ntop inject 12345
$ npx ntop 12345

NTOP allows to connect to a running processes and see "Bottom-Up" of the heaviest functions list like in Dev Tools. It can run in production without adding any overhead. https://github.com/DVLP/ntop

$ npm i -g ntop

Then run the command below where 12345 is the process id (just running ntop shows a list for convenience)

$ ntop inject 12345
$ ntop 12345

Answer 7

In case you are using nodemon to watch over your files, kindly consider using paths to folders with less files. e.g. Letting nodemon watch library folders installed with bower or npm causes the high CPU usage due to thousands of files contained in there.

Here is my sample nodemon.json file:

{
    "watch": ["views","routes"],
    "ext": "html, js"
}

Works like a charm.

Answer 8

maybe you have some computation somewhere using nextTick that is trashing CPU constantly.

If you can't run profile then its hard to find out which method is trashing cpu. One more thing is to examine express log by using logger middleware http://senchalabs.github.com/connect/middleware-logger.html

Answer 9

Another option is we could use Flame Graph and view function invoke cause cpu high. Commands could be found as below

$> git clone https://github.com/brendangregg/FlameGraph.git

$> perf record -F 99 -p 1812 /*process id*/ -g --call-graph dwarf

$> perf script > out.perf

$> FlameGraph/stackcollapse-perf.pl out.perf > out.folded
$> FlameGraph/flamegraph.pl out.folded > out.svg

Answer 10

It maybe because you are amounts of files in the direct. e.g. node_modules folder. you need to use the -i param to ignore that folder. so it should just like this: supervisor -i ./node_modules app.

Answer 11

In my case (a node process, no express), profiling didn't help. It showed no activity whatsoever.

Eventually, I found out it was Chokidar (filesystem watcher), which was set with useFsEvents: false. Removing this property fixed the CPU load from being ~100 to zero.