nodejsアプリケーションで起こっている奇妙な100%CPU使用率の問題を扱っています。アプリはかなり大きく、どこに壊れているのかわからない。このアプリは、pm2によってcluster_modeで管理されます。clockjgettime/gettimeofday/futexのため、Nodejs CPU使用率は100%ですか?
私が知っているすべては、高いCPU使用率の時にstrace
出力する。このです:全体のアプリは、この時点で応答しなく
[email protected]:/# 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
[email protected]:~# 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
[email protected]:~/$ 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まで試しましたが、バージョンは問題なく動作するようです。
この問題はどのようにデバッグできますか?どこから始めますか?
着信コールをログに記録して、デバッグ環境でその状況になるようにシミュレーションを構築することはできますか? – Bernhard
ファイルの変更を監視しながらpm2を実行していますか?私はそれが高いCPU使用率を引き起こしているかどうかを確認することはできません。 –
これをさらに絞り込む必要があります。これは特定のビットのコードが実行されたときにのみ起こりますか?それを別の物理マシンで再現できますか? – tadman