Node.js 100%CPU – gettimeofday调用

我有一个长时间运行的node.js进程,有时会跳转到100%CPU并停止响应请求。 最近一次,我附加了这个过程,这是我看到的:

 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,问题又回来了。 我在这次debugging中取得了一些进展。 第一strace

 $ 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:如何附加到正在运行的进程,并用控制台debugging服务器? 我发现将节点debugging器连接到正在运行的进程,这里是我得到的:

 $ 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 

所以它看起来像是一个定时器,但我不知道如何进一步向上的堆栈来找出在我的代码中的问题是触发。

我的猜测是有人手动实现了一个阻塞“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(); 

当CPU是100%时,使用节点检查器可以暂停你的代码 – 我的赌注也是在一些执行不良的循环检查状态,直到一段时间过去,但是它们很难找到。

在启动节点(即node index.js --debug )时使用–debug附加调试器,并在另一个窗口中运行node-inspector 。 使用Chrome浏览器连接到您的调试会话(该URL是从node-inspector命令输出),并等待,直到问题发生,并暂停执行,你应该能够找到它。

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

它不会被定时循环检查状态,因为一个新的Date()。getTime()循环不会调用gettimeofday(在节点v0.10.29中;它只是在一个pid中进行一连串的nanSleeps,而只是futex调用在其他方面,聪明,实际上)。 相同的Date.now()。

不知道它是否相关,但是这里有一个简单的方法来压缩一个节点进程:当数组中有数据时,使用一个数组作为队列。 这个症状的处理速度非常慢,而且CPU使用率达到100%。

 //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似乎有两个切换点(三种不同的点速度)。 切换点在运行组之间似乎并不相同。

如果调用global.gc()或不调用(使用--expose_gc开关)。 如果按下/移位处于可连续或如上所述的阻塞循环,则无关紧要。

编辑:奇怪的是,这是数据和循环计数相关。 较短的循环运行得更快(即使它们被分成1k批次)。

另外,当这个条件存在的时候,移动/推到其他(空)列表的速度也会减慢到相同的.9k ops / sec(节点v0.10.29),但好奇的是它们可以重叠:每个插入10个并发移位/追加循环.9k项/秒,即总共9k /秒。 (所以有10倍的吞吐量的资源 – 一个内部油门呢?)

编辑:不是内部油门; 慢线程正在使用一个0.8 – 1.2毫秒的CPU的固体块,所有其他线程被阻塞,直到完成。 由于并发线程必须定期产生(我使用setImmediate),所以它们不断被cpu hog后面的阻塞,并相应地进展缓慢。

显式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 

从后到前删除速度快了两倍,但这还是非常慢。 (注:分配到一个新的阵列是50米/秒,但到[]只有25米/秒)

减速是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 ...