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

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

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 results
6. Load v8.log into chrome://tracing to analyse as tree.

node js cpu 100%

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.

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.

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