Node.js 100% CPU -每天调用gettimeofday

Question

我有一个长时间运行的node.js进程，有时会跳转到100%的CPU，并停止响应请求。最近一次它这样做的时候，我把strace附加到了这个过程中，下面是我看到的：

Process 19523 attached - interrupt to quit
gettimeofday({1394558574, 234192}, NULL) = 0
gettimeofday({1394558574, 235381}, NULL) = 0
gettimeofday({1394558574, 306460}, NULL) = 0
mmap(0x3edab823a000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3edab823a000
munmap(0x3edab823a000, 811008)          = 0
munmap(0x3edab8400000, 237568)          = 0
mmap(0x3edab8300000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x3edab8300000
gettimeofday({1394558574, 316435}, NULL) = 0
gettimeofday({1394558574, 316576}, NULL) = 0
gettimeofday({1394558574, 316677}, NULL) = 0
gettimeofday({1394558574, 316775}, NULL) = 0
gettimeofday({1394558574, 316879}, NULL) = 0
gettimeofday({1394558574, 316978}, NULL) = 0
gettimeofday({1394558574, 317439}, NULL) = 0
gettimeofday({1394558574, 317537}, NULL) = 0
gettimeofday({1394558574, 318139}, NULL) = 0
gettimeofday({1394558574, 318234}, NULL) = 0
gettimeofday({1394558574, 318343}, NULL) = 0
gettimeofday({1394558574, 318437}, NULL) = 0
gettimeofday({1394558574, 318530}, NULL) = 0
gettimeofday({1394558574, 318624}, NULL) = 0
gettimeofday({1394558574, 319135}, NULL) = 0
gettimeofday({1394558574, 319648}, NULL) = 0
gettimeofday({1394558574, 319769}, NULL) = 0
gettimeofday({1394558574, 319975}, NULL) = 0
futex(0x7f5b380008c8, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({1394558574, 322266}, NULL) = 0
gettimeofday({1394558574, 322426}, NULL) = 0
gettimeofday({1394558574, 322520}, NULL) = 0
gettimeofday({1394558574, 322759}, NULL) = 0
gettimeofday({1394558574, 322853}, NULL) = 0
gettimeofday({1394558574, 322995}, NULL) = 0
futex(0x7f5b380008c8, FUTEX_WAKE_PRIVATE, 1) = 1
gettimeofday({1394558574, 417614}, NULL) = 0
gettimeofday({1394558575, 386566}, NULL) = 0
gettimeofday({1394558575, 387704}, NULL) = 0
gettimeofday({1394558575, 463410}, NULL) = 0
mmap(0x24cfd260f000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x24cfd260f000
munmap(0x24cfd260f000, 987136)          = 0
munmap(0x24cfd2800000, 61440)           = 0
mmap(0x24cfd2700000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x24cfd2700000

这是大量的gettimeofday调用，而不是其他的！是什么原因导致node.js被困在这样的地方？

UPDATE：我将node.js的旧版本升级到10.29 (我认为)，这一点就消失了。我刚升级到10.33，问题又回来了。这次我在调试它方面取得了更大的进步。第一阶段：

$ sudo strace -p 11812 -c
Process 11812 attached - interrupt to quit
Process 11812 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000192           0      2780           gettimeofday
  0.00    0.000000           0      1390           getrusage
  0.00    0.000000           0        31           futex
  0.00    0.000000           0      1390           clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00    0.000192                  5591           total

从Node.js:如何附加到正在运行的进程并使用控制台调试服务器？中，我了解到如何将节点调试器附加到正在运行的进程中，下面是我从中得到的：

$ sudo kill -s SIGUSR1 11812
$ sudo node debug -p 11812
connecting... ok
break in timers.js:79
  77 }
  78
  79 function listOnTimeout() {
  80   var msecs = this.msecs;
  81   var list = this;
debug> bt
#0 timers.js:79:23

因此，它看起来确实与计时器有关，但我不知道如何在堆栈上进一步移动，以找出代码中的问题是在哪里触发的。

Answer 1

我的猜测是有人手动实现了一个阻塞"setTimeout“。如果有人不想释放对主JS线程的控制，以防止潜在的竞争情况，就可能发生这种情况。

由于明显的原因，这是生产代码的错误实践，但我有时在调试中使用它来强制异步进程按特定顺序执行。

你可以找一些像这样的傻事：

var mockAsyncFunction = function (cb) {
    setTimeout(function () {
        cb(null, 'dummy_result')
    }, 5000);
};

var myResult = null;
mockAsyncFunction(function (err, result) {
    myResult = result;
});
var timeOut = 10000; // timeout in 10 sec.
var timeStart = new Date().getTime();


while (1) {
    if (new Date().getTime() - timeStart > 10000) {
        break;
    }
}
console.log('DONE');

或者使用nextTick递归的更邪恶的东西，比如：

var timeStart = new Date().getTime();

var recurseUntilDone = function () {
    if (new Date().getTime() - timeStart < 10000) {
        process.nextTick(recurseUntilDone);
    } else {
        console.log('Done recursing');
    }
};

recurseUntilDone();

Answer 2

使用节点检验员可以在CPU为100%时暂停您的代码--我的赌注也是在某些未实现的循环检查状态上，直到某个时间过去，但它们可能很难找到。

在启动节点时使用--调试附加调试器(即.( node index.js --debug)并在单独的窗口中运行node-inspector。使用Chrome连接到您的调试会话( url是从节点检查器命令中输出的)，等待问题发生并暂停执行，您应该能够找到它。

Answer 3

我们在生产和发展中也看到了这一点。同时也在寻找答案。我们开始调查节点运行时，但是这个问题很少发生，所以没有任何优先级。因为它完全是cpu绑定的，没有系统调用，所以很难用strace捕获。

它不会是定时循环检查状态，因为一个新的Date().getTime()循环不会调用gettimeofday (在节点v0.10.29中；它只是在一个pid中执行一系列纳秒级操作，在另一个pid中只执行futex调用)。其实很聪明)。Date.now()也是如此。