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가 데리러 인해 '제로 메모리를보고'에 프로세스를 다시 시작 : 분명히이가 PM2의 버그로 인해 발생

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 

: https://github.com/Unitech/pm2/issues/2492합니다. 그러나 버그가 고쳐지면 프로세스가 다시 시작되지 않아 멈추게됩니다. 이제는 이전 버전을 고수 할 수 밖에 없습니다.

나는 그 과정을 시작하는 데 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, 스왑 리소스가 있습니다.

우분투 (루마니아 의존성 업그레이드와 함께 nodejs 및 mongodb를 업그레이드 한 apt-get 업그레이드)에 대한 일상적인 유지 보수 후에 문제가 발생하기 시작했습니다. 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++)입니다.

누군가 다른 사람이 유사한 문제에 대한 해결책을 검색하는 경우를 대비하여 질문과 대답을 남겨 두었습니다.