Java スレッドダンプとの戯れ方

プロセスIDの取得

まずは Java のプロセスIDを取得するところから始める。jps で取得できる。

$ <JAVA_HOME>/bin/jps -l

主要なオプションは以下の通り(SunVM)。

オプション	説明
-m	main メソッドに渡される引数を出力
-l	アプリケーションの主要なクラスのフルパッケージ名、またはアプリケーションの JAR ファイルへのフルパス名を出力
-v	JVM に渡される引数を出力

JDK7 からは JRockit と統合されたため jcmd が使えるので以下でもプロセスIDを取得できる。

$ <JAVA_HOME>/bin/jcmd

または、単に ps コマンドで取得するでもよい。

$ ps -ef | grep -v 'grep' | grep java

さらに、java.io.tmpdir プロパティで指定されたディレクトリにできるhsperfdata_<USER_ID> ファイルの中身をのぞき見てもプロセスIDを得ることができる。 大抵は /tmp とか C:\Users\<username>\AppData\Local\Temp\ などになっている。

Windows プラットフォームの場合タスクマネージャにプロセスID列を追加して確認してもよい。

スレッドダンプの取得

先の手順で取得したプロセスIDで jstack コマンド叩けばスレッドダンプが取得できる。

$ <JAVA_HOME>/bin/jstack <JAVA_PID> > jstack_dump.txt

または、単に SIGQUIT シグナル送るでもよい。

$ kill -3 <JAVA_PID>

ただ、この場合プロセスの標準出力にスレッドダンプが出力されるので少し扱いづらい。

Windows でプロセス実行中のコマンドプロンプトがある場合には、Ctrl+Break で標準出力に出力することもできる。

jcmd の場合は以下でも同様。

$ <JAVA_HOME>/bin/jcmd <JAVA_PID> Thread.print

Windowsでプロセスをサービス起動している場合

Windowsでプロセスをサービス起動していると、プロセスが System アカウントで実行されるため jps などでプロセスも見えないし、jstack でスレッドダンプも取れない。

この場合はタスクスケジューラ利用するか、at コマンドによりSystem アカウントで実行する。

以下のようにプロセスIDを確認し、

> at 12:34 cmd /c "C:¥Program Files¥Java¥jdk1.7.0_xx¥bin¥jps.exe" ^> jps.txt 2^>^&1

jstack でダンプ取得。

> at 12:35 cmd /c "C:¥Program Files¥Java¥jdk1.7.0_xx¥bin¥jstack.exe" <JAVA_PID> ^> jstack_dump.txt 2^>^&1

at とすることで現在スケジューリングされているタスクが確認でき、at /delete <タスクID> などで消したり。

上記で上手くいかない場合は、Schtasks を使う。

SCHTASKS /Create /tn "JPS" /tr "cmd.exe /c 'C:¥Program Files¥Java¥jdk1.7.0_xx¥bin¥jps.exe' > C:\jps.txt 2>&1" /RU SYSTEM /SC ONCE /ST 12:34

/TN タスク名、/TR 実行するタスク、/SC スケジュールの頻度、/ST 開始時刻

/RU でシステムアカウントを指定する。

タスクはタスクスケジューラに登録されるので、タスクスケジューラから編集できる。タスクの削除は以下。

SCHTASKS /Delete /tn "JPS"

時刻指定が面倒な場合は、PsExec ツール(rsh や rexec のようなコマンド)を使うこともできる。 こちら https://technet.microsoft.com/ja-jp/sysinternals/bb897553 から落として解凍し、中にあるpsexecを実行すればよい。

-s オプションで実行すると System アカウントでコマンド実行できる。

> psexec -s "C:¥Program Files¥Java¥jdk1.7.0_xx¥bin¥jstack.exe" <JAVA_PID> > jstack_dump.txt

スレッドダンプを読む

ダンプの中身は以下のような感じになる。

"File Watcher" #27 daemon prio=1 os_prio=31 tid=0x00007fdf878a9800 nid=0x11c03 waiting on condition [0x0000700003782000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000780c95760> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)

出力される内容は大体以下。

項目	内容
スレッド名	"File Watcher" #27 のようなスレッド名
スレッドタイプ	デーモンスレッドの場合 daemon と出る
prio	優先度でjava.lang.Thread.priority の値。10が最大優先度
os_prio	OS上のスレッド優先度
tid	VM上のスレッドIDで複数ダンプのスレッドをこの値で追跡できる
nid	OS上のスレッドID
状態	java.lang.Thread.Stateで定義されたスレッドの状態

tid は、同じスレッドで一意となるので、複数回スレッドダンプを取得し、スレッドの状況を追従するのに重要。

状態の定義は JavaDoc に書いてある。

状態	説明
NEW	起動していないスレッドの状態
RUNNABLE	Java 仮想マシンで実行されているスレッドの状態
BLOCKED	ブロックされ、モニターロックを待機しているスレッドの状態
WAITING	ほかのスレッドが特定のアクションを実行するのを無期限に待機しているスレッドの状態
TIMED_WAITING	指定された待機時間、ほかのスレッドがアクションを実行するのを待機しているスレッドの状態
TERMINATED	終了したスレッドの状態

スレッドダンプ中の nid はOSのネイティブスレッドの ID を 10進->16進 に変換したものとなる。

OS側のスレッドIDは

$ top -H

とすることでスレッドが表示されるので、ここで得たIDを16進変換してnidと対応づけることができる。

または ps でスレッド表示して、LWP の項目を16進変換してnidと当てることもできる。

$ ps auxww -L | grep -v grep | grep -e ・・・ 

Windowsの場合はパフォーマンスモニタでスレッドのカウンタを追加するか、Process Explorer などを使ってスレッドIDを得ればよい(対象プロセスを選択し、プロパティダイアログ内で確認できる)。

Javaパフォーマンス