Recentemente analisando um Enterprise Manager Cloud Control (EMCC) que apresentava lentidão na navegação entre as páginas e visualização dos gráficos. Conectando no servidor, o load e uso de memória estavam baixos, mas havia um processo do EM mostrando mais de 100% de utilização de CPU na saída do top:
$ top
top - 11:18:28 up 9 days, 16:29, 2 users, load average: 1.13, 1.37, 1.43
Tasks: 394 total, 1 running, 313 sleeping, 0 stopped, 0 zombie
%Cpu(s): 24.6 us, 0.5 sy, 0.0 ni, 74.7 id, 0.0 wa, 0.2 hi, 0.1 si, 0.0 st
KiB Mem : 32591404 total, 3157428 free, 20602532 used, 8831444 buff/cache
KiB Swap: 16773116 total, 16773116 free, 0 used. 10824760 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28634 oracle 20 0 8421380 3.2g 81372 S 189.6 10.4 6251:56 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -+
28269 oracle 20 0 7207800 1.5g 59612 S 4.3 4.7 315:00.21 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1024M -XX:CompileThreshold=8000 -+
3424 oracle 20 0 6036768 562692 26072 S 1.2 1.7 73:53.98 /u01/app/oracle/agent/agent_13.4.0.0.0/oracle_common/jdk/bin/java -Xmx167M -XX:MaxMetaspaceSize=224M -server+
2517 grid 20 0 2574060 119240 68424 S 0.6 0.4 36:48.55 /u01/app/19.0.0/grid/bin/ohasd.bin reboot
3502 grid 20 0 499244 34580 25976 S 0.6 0.1 21:39.45 /u01/app/19.0.0/grid/bin/evmd.bin
Dei um strace no processo e notei que o mesmo estava travado nesse evento:
$ strace -p 28634
strace: Process 28634 attached
futex(0x7fd93f48b9d0, FUTEX_WAIT, 28635, NULL
Pesquisando em algumas referências do Linux, entendi que esse evento é uma espécie de “lock” no kernel do sistema operacional, assim como temos lock no banco de dados.
Usei o comando strace novamente, com a opção -f para ver a atividade de todas as threads (sub processos) vinculados com esse PID, e também usei a opção -o para direcionar a saída para um arquivo:
$ strace -p 28634 -f -o 28634.txt
Aguardei alguns segundos e consultei o conteúdo do arquivo “28634.txt”:
$ tail 28634.txt
28669 futex(0x7fd93a583628, FUTEX_WAKE_PRIVATE, 1) = 0
28669 futex(0x7fd93a583654, FUTEX_WAIT_BITSET_PRIVATE, 1, {tv_sec=847252, tv_nsec=967181486}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out)
28669 futex(0x7fd93a583628, FUTEX_WAKE_PRIVATE, 1) = 0
28669 futex(0x7fd93a583654, FUTEX_WAIT_BITSET_PRIVATE, 1, {tv_sec=847253, tv_nsec=17451825}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out)
28669 futex(0x7fd93a583628, FUTEX_WAKE_PRIVATE, 1) = 0
28669 futex(0x7fd93a583654, FUTEX_WAIT_BITSET_PRIVATE, 1, {tv_sec=847253, tv_nsec=67820836}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out)
28669 futex(0x7fd93a583628, FUTEX_WAKE_PRIVATE, 1) = 0
28669 futex(0x7fd93a583654, FUTEX_WAIT_BITSET_PRIVATE, 1, {tv_sec=847253, tv_nsec=118166905}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out)
Haviam várias threads realizando varias atividades, mas essa com PID 28669 sempre apresentava essa mensagem relacionada “futex” e com ” Connection timed out”.
Usei o comando top novamente, usando a opção -p para filtrar o processo do EM, e a opção -H para listar todas as threads:
$ top -H -p 28634
top - 14:11:09 up 9 days, 19:22, 3 users, load average: 1.54, 1.54, 1.56
Threads: 300 total, 2 running, 298 sleeping, 0 stopped, 0 zombie
%Cpu(s): 12.8 us, 0.3 sy, 0.0 ni, 86.6 id, 0.0 wa, 0.3 hi, 0.1 si, 0.0 st
KiB Mem : 32591404 total, 2509900 free, 20793872 used, 9287632 buff/cache
KiB Swap: 16773116 total, 16773116 free, 0 used. 10633344 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
28647 oracle 20 0 8357892 3.2g 81364 R 99.0 10.3 1197:48 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28634 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.00 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28635 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:01.55 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28636 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 62:50.21 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28637 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 65:16.33 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28638 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 62:25.66 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28639 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 62:40.01 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28640 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 62:21.21 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28641 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 65:02.83 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28642 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 62:37.29 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28643 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 63:10.09 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28644 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 490:53.19 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28645 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 490:54.14 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28646 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 422:49.30 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28648 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:03.31 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28649 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:10.20 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28661 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:01.59 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28662 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.00 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28664 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 539:36.65 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28665 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 540:42.70 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28666 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 540:22.47 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28667 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 324:04.49 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28668 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:43.62 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28669 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 6:14.91 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28671 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.00 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28677 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.00 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28682 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:41.25 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28683 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 10:32.57 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28684 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.41 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28685 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 7:23.37 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28688 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 11:24.78 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28689 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 8:20.52 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28690 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 12:26.69 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28691 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 21:43.03 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28692 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 15:06.53 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28693 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 15:41.80 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28694 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 15:26.90 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28695 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:56.57 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28696 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 10:27.17 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28697 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.08 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
28698 oracle 20 0 8357892 3.2g 81364 S 0.0 10.3 0:00.00 /u01/app/oracle/middleware/oracle_common/jdk/bin/java -server -Xms256M -Xmx1740M -XX:CompileThreshold=8000 -X+
Como podemos ver, o processo do EM abre várias threads java. Nesse caso específico, testei matar o processo 28669 individualmente, ao invés de reiniciar o serviço do EM:
$ kill -9 28669
Após matar a thread que apresentava mensagens de “mutex” e “timeout”, o processo principal do EM saiu do estado de FUTEX_WAIT e a performance normalizou.
Referência: