Nodejs 100% загрузка процессора из-за clock_gettime/gettimeofday/futex?

Question

Я имею дело с странной 100% проблемой использования ЦП, происходящей с приложением nodejs. Приложение довольно велико, и я не уверен, где он сломан, что вызвало это. Приложение управляется pm2 в cluster_mode.

Все, что я знаю, во время высокой загрузки процессора, 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 подберут и перезапустить процесс из-за «сообщила нулевая память»:

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: 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, swap ресурсов, чем необходимо.

Проблема возникла после некоторого рутинного обслуживания на ubuntu (apt-get upgrade, который обновил nodejs и mongodb, вместе с обновлениями на npm-зависимостях). Обновление nodejs прошло с 4.6.1 до 4.6.2. Но когда я понизился до 4.6.1, проблема все еще там. Я пробовал до 4.4.7 и 6.9.1, ни одна версия не работает без проблем.

Как отладить эту проблему? С чего начать?

Answer 1

Методы отладки в моем вопросе неверны. Я делаю такую ​​отладку только потому, что результаты Google указали на меня таким образом, когда вы искали «nodejs 100% cpu usage». И они оказались обманчивыми.

Правильная техника заключается в том, чтобы позволить самому узлу разрешить отладку через node --debug=7000, например. В точке высокой загрузки процессора запустите клиент отладки node debug localhost:7001. И приостановите выполнение с помощью pause. Попробуйте сделать паузу и запустить несколько раз, и вы сможете определить местоположение выполнения.

Оказалось, что это бесконечная петля, то есть for (i=10; i>=0; i++).

Я оставляю вопрос и отвечу здесь, если кто-то ищет решение для подобного поведения.