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

Solution 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%

Solution 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.

Solution 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.

Solution 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

Solution 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.

View more solutions

Comments

[laggingreflex]

possible duplicate of node js cpu 100%

[Tim]

I don't use nextTick and the logs just show normal operation. Will the v8 profiler show which method is causing it? Is there any other options for profilers other than node-inspector?

[Milan Babuškov]

Tim, could you explain why return is needed? Wouldn't node simply just go out of scope since there are no more commands in the function?

[Tim]

I have got into the habit of returning any callback that is the last statement. I got this tip from stella.laurenzo.org/2011/03/bulletproof-node-js-coding . It was a problem in my app because it was doing callback(err) without returning. Therefore, express returned a result to the user but the request was still trapped in a while loop (an async version).

[Maxim Yefremov]

@Tim How did you figure out the problem piece of code by replaying history?

[JimTheDev]

This works perfectly on iojs as well. Just swap node --prof ./app.js for iojs --prof ./app.js. There are a bunch of packages that currently don't work in iojs and often they will result in 100% cpu. If any of your package's dependencies rely upon the ncp package for example then they will possibly result in 100% cpu usage. Depending on your use case, you may be able to swap out ncp for npmjs.com/package/ember-cli-copy-dereference instead.

[Yehonatan]

This doesn't seem like the real problem. If there's an unused callback, which does nothing but taking memory then it would've been GCed.

[beauXjames]

I really, really wanted this to be a set of steps that would answer my question, however after attaining the v8.log when I run node-tick-processor there is no response (cmd just sits there) and if I open the same log file in the chrome://tracing module everything just reports a bunch of (empty). In a text editor I see loads of action (125MB worth) however I do not know how to interpret this information.

[Esqarrouth]

link broken, fix or delete post please