clockjgettime/gettimeofday/futexのため、Nodejs CPU使用率は100％ですか？

Question

nodejsアプリケーションで起こっている奇妙な100％CPU使用率の問題を扱っています。アプリはかなり大きく、どこに壊れているのかわからない。このアプリは、pm2によってcluster_modeで管理されます。

私が知っているすべては、高いCPU使用率の時にstrace出力する。このです：全体のアプリは、この時点で応答しなく

root@a:/# strace -p 4350 -c 
Process 4350 attached 
% time  seconds usecs/call  calls errors syscall 
------ ----------- ----------- --------- --------- ---------------- 
100.00 0.000031   0  3388   clock_gettime 
    0.00 0.000000   0   1   read 
    0.00 0.000000   0   2   write 
    0.00 0.000000   0   1   rt_sigreturn 
------ ----------- ----------- --------- --------- ---------------- 
100.00 0.000031     3392   total 

root@a:~# strace -p 3367 -r -c 
Process 3367 attached 
^CProcess 3367 detached 
% time  seconds usecs/call  calls errors syscall 
------ ----------- ----------- --------- --------- ---------------- 
75.00 0.000939   0  91973   gettimeofday 
25.00 0.000313   0  39417   clock_gettime 
------ ----------- ----------- --------- --------- ---------------- 
100.00 0.001252    131390   total 

。約5分後、pm2がピックアップするとによる「ゼロメモリが報告」にプロセスを再起動します。https://github.com/Unitech/pm2/issues/2492：

2016-12-03-20:29:05 PM2 [PM2][WORKER] Process 1 restarted because it uses 0 memory and has ONLINE status 
2016-12-03-20:29:05 PM2 Stopping app:api-v2 id:1 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:06 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still not killed, retrying... 
2016-12-03-20:29:07 PM2 Process with pid 3367 still alive after 1600ms, sending it SIGKILL now... 
2016-12-03-20:29:07 PM2 App name:api-v2 id:1 disconnected 
2016-12-03-20:29:07 PM2 App [api-v2] with id [1] and pid [3367], exited with code [0] via signal [SIGKILL] 
2016-12-03-20:29:07 PM2 Starting execution sequence in -cluster mode- for app name:api-v2 id:1 
2016-12-03-20:29:07 PM2 App name:api-v2 id:1 online 

どうやらこれは、PM2のバグが原因です。しかし、バグが修正された場合、プロセスを再起動しないため、古いバージョンに固執するしかありません。

私は、その後、プロセスを開始するtimeとstraceを使用する場合：

real 0m45.765s 
user 0m3.349s 
sys 0m0.340s 
www-data@a:~/$ strace -cf node /var/www/api-v2.js 
Process 4020 attached 
... 
% time  seconds usecs/call  calls errors syscall 
------ ----------- ----------- --------- --------- ---------------- 
99.09 9.247853  4538  2038  26 futex 
    0.18 0.016793   1  17777   clock_gettime 
    0.16 0.015384   12  1262   epoll_wait 
    0.11 0.010522   116  91   poll 
    0.09 0.008339   2  5237  2437 stat 
    0.08 0.007856   6  1234   write 
    0.05 0.004309   3  1571   close 
    0.03 0.003150   2  1790   read 
    0.03 0.003150   2  1333  248 open 
    0.03 0.003046   11  265   mmap 
    0.02 0.002049   2  1186   lstat 
    0.02 0.001617   4  378   madvise 
    0.02 0.001535   2  917   fstat 
    0.02 0.001518   1  1773   gettimeofday 
    0.01 0.001096   1  1224  35 epoll_ctl 
    0.01 0.000983   3  329  37 connect 
    0.01 0.000792   1  667  329 accept4 
    0.01 0.000734   10  76   brk 
    0.01 0.000617   2  338   pread 
    0.00 0.000315   2  155   socket 
    0.00 0.000265   9  30   sendmmsg 
    0.00 0.000184   1  144   munmap 
    0.00 0.000162   1  113   mprotect 
    0.00 0.000125   4  35   sendto 
    0.00 0.000114   7  16   setsockopt 
    0.00 0.000078   1  60   recvfrom 
    0.00 0.000071   1  105   recvmsg 
    0.00 0.000064   2  35   writev 
    0.00 0.000052   7   8   clone 
    0.00 0.000049   2  20  20 access 
    0.00 0.000043   0  192   getsockname 
    0.00 0.000029   7   4   getdents 
    0.00 0.000024   1  36   bind 
    0.00 0.000023   23   1   readlink 
    0.00 0.000020   1  35   getsockopt 
    0.00 0.000019   19   1   execve 
    0.00 0.000018   0  86   9 ioctl 
    0.00 0.000011   2   5   rt_sigprocmask 
    0.00 0.000009   5   2   openat 
    0.00 0.000006   1  11   getcwd 
    0.00 0.000005   5   1   lseek 
    0.00 0.000005   0  35   rt_sigaction 
    0.00 0.000003   3   1   arch_prctl 
    0.00 0.000000   0   1   listen 
    0.00 0.000000   0  14   uname 
    0.00 0.000000   0   2   getrlimit 
    0.00 0.000000   0   2   getuid 
    0.00 0.000000   0   1   getgid 
    0.00 0.000000   0   1   geteuid 
    0.00 0.000000   0   1   getegid 
    0.00 0.000000   0   4   prctl 
    0.00 0.000000   0   1   setrlimit 
    0.00 0.000000   0   1   set_tid_address 
    0.00 0.000000   0   1   clock_getres 
    0.00 0.000000   0   9   set_robust_list 
    0.00 0.000000   0   1   eventfd2 
    0.00 0.000000   0   1   epoll_create1 
    0.00 0.000000   0   2   dup3 
    0.00 0.000000   0   2   pipe2 
------ ----------- ----------- --------- --------- ---------------- 
100.00 9.333037     40661  3141 total 

私は自分のコード内の任意のsetTimeoutのコールを持っていないが、私はありません依存関係を持っている想像してみてください。私は最近の変更を見直しました。再帰呼び出しや決して終了しないループは含まれていません。

メモリリークがゼロであることがわかりました。つまり、pm2のメモリサイズは時間外に増加しませんでした。以前は同じプログラムが再起動せずに2ヶ月間実行されていました。サーバーには、必要以上に多くのCPU、RAM、スワップリソースがあります。

ubuntu（apt-getをアップグレードしてnodejsをアップグレードしたmongodbとnpmの依存関係のアップグレード）に関するいくつかのルーチンmaintenaceの後に問題が発生し始めました。 nodejsのアップグレードは4.6.1から4.6.2になりました。しかし、私が4.6.1にダウングレードしても、問題はまだ残っています。私は4.4.7と6.9.1まで試しましたが、バージョンは問題なく動作するようです。

この問題はどのようにデバッグできますか？どこから始めますか？

Answer 1

私の質問のデバッグ手法は間違っています。私はそのようなデバッグをしているのは、あなたが「nodejs 100％cpu utilization」を検索したときにGoogleの結果が私に指摘したからです。そして、彼らは誤解を招くようになった。

正しい手法は、たとえばノードnode --debug=7000によってデバッグを許可することです。 CPU使用率が高い時点で、デバッグクライアントnode debug localhost:7001を実行します。そして、pauseで実行を一時停止します。一時停止して数回実行すると、実行の場所を特定できるようになります。

無限ループ状態であることが判明しました。つまり、for (i=10; i>=0; i++)です。

他の人が同じような動作をするソリューションを検索する場合は、ここで質問と回答を残しておきます。