Node.js 100% CPU - gettimeofday 调用答案

【问题标题】：Node.js 100% CPU - gettimeofday callNode.js 100% CPU - gettimeofday 调用
【发布时间】：2014-04-16 02:49:34
【问题描述】：

我有一个长时间运行的 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 像这样卡住？

更新：我从旧版本的 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: How to attach to a running process and to debug the server with a console? 我发现了如何将节点调试器附加到正在运行的进程，这就是我得到的地方：

$ 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

所以看起来它肯定与计时器有关，但我不知道如何进一步向上移动堆栈以找出问题在我的代码中被触发的位置。

【问题讨论】：

您使用的是“时间条件变量”吗？ npmjs.org/package/condvar
@AlexejMagura 这是一个大型应用程序，所以我不能全部发布，而且我不知道从哪里开始将其追溯到负责的代码。
我建议使用分析器找出泄漏的来源，而不是通过更改代码手动搜索。看看：github.com/felixge/node-memory-leak-tutorial 和/或 github.com/node-inspector/node-inspector
您是否尝试过通过 JSHint 或其他分析工具运行所有代码？我怀疑这是一个永无止境的循环。
从目前为止所说的一般情况下考虑这一点：您是否有任何类型的队列正在备份“重试”类型的事件，这些事件最终会得到处理？您说它最终恢复正常的事实让我认为某处（在您的代码或库中）可能是每个都在争夺/检查某种资源的可用性的事物的瓶颈。在正常操作中可能微不足道，但如果出现后备情况......在使用量等方面出现问题时是否有任何线索？

标签： javascript linux node.js strace

【解决方案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();

【讨论】：

当我查看 nextTick 递归时，我在 node v0.10 中遇到了一个调用堆栈超出错误 Node v0.11 支持它
从内部节点调用 gettimeofday() 是什么？一个新的 Date.getTime() 循环不会
@Andras 我认为它被 setTimeout 使用了
我刚试过，好像不行。它多次调用 nanosleep 0.9 毫秒（没有我设置的 setTimeouts 那么多，但有点成比例）

【解决方案2】：

使用node-inspector 可以在 CPU 为 100% 时暂停您的代码 - 我敢打赌，在经过一定时间之前，某些执行不良的循环检查状态也很重要，但它们可能很难找到。

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

【讨论】：

【解决方案3】：

我们在生产和开发中也看到了这一点。也在寻找答案。我们开始调查节点运行时，但问题非常罕见，没有得到任何优先级。因为它完全受 cpu 限制，没有系统调用，所以很难用 strace 捕获。

它不会是定时循环检查状态，因为新的 Date().getTime() 循环不会对 gettimeofday 进行任何调用（在节点 v0.10.29 中；它只是在一个 pid 中执行一长串 nanosleeps 并且只是 futex 调用另一个。实际上很聪明）。 Date.now() 也一样。

【讨论】：

有趣。我刚刚确认 setInterval 和 setTimeout 都调用 clock_gettime 而不是 gettimeofday。
node.js 代码中没有那么多引用它：github.com/joyent/node/…
是的，我也摸索过，LinuxSemaphore::Wait 看起来可行，但我在试图从那里追踪时陷入困境，要检查的地方太多（我在本地克隆了源 git）
我也面临同样的问题？ @Andras 如果为您解决了这个问题，您能否提供解决此问题的线索？

【解决方案4】：

不知道是否相关，但是这里有一个简单的方法来粉碎节点进程：当它有数据时，使用数组作为队列。症状是处理速度非常非常慢，而且 100% 的 cpu 使用率。

//a = [];
a = new Array();

for (i=0; i<87370; i++) a.push({});

for (i=0; i<1000000; i++) {
    a.shift();
    a.push({});
    if (i%1000 === 0) {
    process.stdout.write(".");
    //global.gc();
    }
}

// node v0.10.29: 10k:  0.15 sec
//        80k:  0.17 sec
//        87369: 0.17 sec
//            87370: instant 41k, then .9k per second
//        87400: Array: instant 41k, then .9k per second
//        87400: []: instant 28k, then .9k per second
//        87400: Array, pushing 1 or 'x': .9k per second from the start
// node v0.11.13: 10k: 1.94 sec
//        16683: 3.87 sec
//        16884: uniform 237.16 sec

我跑了perf record -F 997 -g node-v0.11.13 --perf-basic-prof script.js，但几乎所有时间都归因于 Builtin_ArrayShift（从 ~ 调用 5-6 个不同的十六进制位置）

请注意，该行为有一个切换点，低于它的速度很快，高于它的速度很慢。 0.10 和 0.11 的行为是不同的； 0.11 似乎有两个切换点（3 个不同的点速度）。各组运行之间的切换点似乎并不相同。

是否调用 global.gc() 无关紧要（使用--expose_gc 开关）。推/移是在可连续循环还是在像上面那样的阻塞循环中都没有关系。

编辑：奇怪的是，这取决于数据和循环计数。较短的循环运行得更快（即使它们被分成 1k 个批次）。

此外，当这种情况存在时，转移/推送到其他（空）列表也会减慢到相同的 0.9k 操作/秒（节点 v0.10.29），但奇怪的是它们可以重叠：10 个并发转移/追加循环每个将插入 0.9k 个项目/秒，即总共 9k/秒。（所以有资源可以将吞吐量提高 10 倍——那么内部限制？）

编辑：不是内部油门；慢速线程正在使用 0.8 - 1.2 毫秒的 cpu 块，所有其他线程都被阻塞，直到它完成。由于并发线程必须定期让步（我使用了 setImmediate），因此它们会一直被阻塞在 CPU 猪后面并相应地导致进度缓慢。

【讨论】：

【解决方案5】：

来自较大散列或数组的显式delete，例如清理内部数据容器，也可能导致此类症状。固有的节点操作可能非常缓慢：

h = {}
for (i=0; i<200000; i++) h[i] = i;     // 25,000,000 / sec
for (i=0; i<1000; i++) delete h[i];    // 11,000 / sec
for (i=0; i<200000; i++) delete h[i];  // 7,700 / sec

a = new Array();
for (i=0; i<200000; i++) a[i] = i;     // 50,000,000 / sec
for (i=0; i<1000; i++) delete a[i];    // 10,000 / sec
for (i=0; i<200000; i++) delete a[i];  // 8,000 / sec
// and out of curiousity...
for (i=0; i<200000; i++) a[i];         // 250,000,000 / sec
for (i=1; i<200000; i++) a[i-1] = a[i]; // 180,000,000 / sec

从后到前删除速度快了 2 倍，但这仍然很慢。（注意：分配到一个新的 Array 是 50m/s，但是分配到 [] 只有 25m/s）

减速是 O(n^2)：将数组大小翻倍至 400k 使运行时间翻了两番。每个删除操作都是散列/数组大小的 O(n)。

400k 运行（100 秒）的 strace 显示没有系统调用可言，并且与上面看到的 gettimeofday() 模式不匹配。

...
14:08:36.327886 munmap(0x44200000, 802816) = 0
14:08:36.328145 munmap(0xf7100000, 1183744) = 0
14:08:36.328483 clock_gettime(CLOCK_REALTIME, {1418584116, 328495018}) = 0
14:08:36.328540 clock_gettime(CLOCK_REALTIME, {1418584116, 328551680}) = 0
14:08:36.328581 clock_gettime(CLOCK_REALTIME, {1418584116, 328592628}) = 0
14:08:36.328633 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1
14:09:03.130336 clock_gettime(CLOCK_REALTIME, {1418584143, 130406483}) = 0
14:09:03.130479 clock_gettime(CLOCK_REALTIME, {1418584143, 130503357}) = 0
14:09:03.130560 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1
14:09:37.090127 clock_gettime(CLOCK_REALTIME, {1418584177, 90195108}) = 0
14:09:37.090271 clock_gettime(CLOCK_REALTIME, {1418584177, 90296760}) = 0
14:09:37.090355 futex(0x8e79a7c, FUTEX_WAKE_PRIVATE, 1) = 1
14:10:17.588552 mmap2(0x3f302000, 4231168, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x3f302000
14:10:17.588694 munmap(0x3f302000, 1040384) = 0
14:10:17.588768 munmap(0x3f709000, 8192) = 0
...

【讨论】：

【解决方案6】：

如果还有人遇到这个问题，我也会遇到这个问题（严重到我的“重复”节点每秒开始丢弃指令）。

在我的情况下，这是由“串行”节点引起的 - 您可以通过启动 htop 命令来监控 CPU 使用情况，然后在删除“串行输入”节点后重新部署所有节点。

CPU 使用率应立即回落。

【讨论】：