#1.事の発端
Tomcat上で動いているjavaアプリケーションで、CPUがずっと80%とかにくっついている現象が発生。
「うぇーまじか」となった。
ともあれ調査せねば。となった時にやったこと。
#2.手順
#2.1 topコマンドで状況確認(当時のものとは違っています)
コマンド
$ top
top - 18:27:24 up 285 days, 3:05, 3 users, load average: 5.33, 5.36, 4.93
Tasks: 70 total, 1 running, 69 sleeping, 0 stopped, 0 zombie
Cpu(s): 10.1%us, 0.9%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 89.0%st
Mem: 617044k total, 522324k used, 94720k free, 4812k buffers
Swap: 0k total, 0k used, 0k free, 79684k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1722 root 20 0 1422m 394m 6004 S 96.5 65.5 53:50.89 jsvc
6 root 20 0 0 0 0 S 3.4 0.0 11:35.37 events/0
1929 hoge 20 0 2592 1000 784 R 0.3 0.2 0:24.33 top
1 root 20 0 2892 868 664 S 0.0 0.1 0:01.76 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
--- (以下略) ---
#2.2 プロセスでヤバそうな奴を見つける
$ ps -L aux
そうすると、tomcat上で動くプログラムのうちいくつかにおける(TIME)が永遠と増え続けていることに気付く。
コマンド
USER PID LWP %CPU NLWP %MEM VSZ RSS TTY STAT START TIME COMMAND
tomcat 3487 1111 25.1 39 14.1 10233084 2222644 ? Sl 09:03 25:10 jsvc.exec -user tomcat -home /usr/lib/jvm/java
こんな感じ(イメージです)。
PIDとLWPを控える。
#2.3スレッドダンプを取得
rootユーザで
su - tomcat -s /bin/bash
jstack PID(先ほど控えた奴)
そうすると以下みたいな情報が出てくるので、控えるなり、目を背けるなりする
スタックトレース(例)
"RMI TCP Accept-0" #10 daemon prio=5 os_prio=0 tid=0x0000000000c29800 nid=xxxx runnable [0x00007f2f36728000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
--- (以下略) ---
16進数にしたLWPのIDがスレッドダンプ内の"nid=xxxxx" と対応する
なのでスレッドダンプしたファイルをそのIDで検索してやれば、対象のスタックトレースが見つかる
- LWP: Linux上のプロセスよりも小さい実行単位、スレッドのようなもの
#2.4 終わってみて
調査してみたところ、再帰処理で死亡していたことが判明。修正し一段落