Javaトラブルに応じた初動対応のまとめ

Javaトラブルでは『情報がなくて、再現もなかなかしません』といった状況に陥ることがある。このような状況を回避するために、以下の3つの代表的なトラブルを例に、アプリケーションサーバを再起動する前に何を取得すれば良いのかをまとめてみる。

• アプリケーションから応答がない
• アプリケーションが遅い
• ヒープメモリが足りない(OutOfMemoryErrorの発生)

アプリケーションから応答がない

取得する情報

• スレッドダンプ

データ取得方法

スレッドダンプとは、コマンド実行時点でのJavaスレッド実行状態を出力したものである。応答がない場合、何らかの要因によりどこかで処理が止まっていることが想定される。スレッドダンプは『どこで止まっているのか？』を切り分けるのに大切な情報である。

取得方法はJDKのバージョンによって色々ある。

• kill -3 <pid> (少なくとも1.4.2にはある〜JDK7でも有効)
• ${JAVA_HOME}/bin/jstack <pid> (JDK5/JDK6/JDK7)
• ${JAVA_HOME}/bin/jcmd <pid> Thread.print (JDK7)

いずれの操作も、Java起動プロセスと同じユーザで実行すること。kill -3 で出力した場合は標準出力にスレッドダンプが出力されてしまうので、若干使い勝手が悪い。jstackかjcmdで取得するのが個人的にお勧め。

試しに、Wildfly8でコネクションプールを枯渇させてコネクションの取得待ち状態にさせたスレッドダンプを取得してみる。

"default task-10" prio=5 tid=0x00007fef5bb8d000 nid=0xb307 waiting on condition [0x000000011090a000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000007fea15470> (a java.util.concurrent.Semaphore$FairSync)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
    〜 省略 〜
    at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:142)
    at slowweb.SlowServlet.processRequest(SlowServlet.java:44)
    at slowweb.SlowServlet.doGet(SlowServlet.java:78)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)

トラブル発生時に複数回スレッドダンプを発生し、解析ツールである侍に読み込ませてスレッド状態の遷移確認することが多い。

アプリケーションが遅い

取得する情報

• プロファイラ (テスト環境で再現できる場合)
• スレッドダンプ

データ取得方法

プロファイラについては、無償で使える手軽なJDK付属のhprofがある。cpu=timeにすると遅すぎて情報収集にならないので、cpu=sampleでサンプリングしたデータで通常は十分。hprofを起動するには、Java起動オプションに"-agentlib:hprof=cpu=samples"を追加する。

設定例は以下の通り。

-agentlib:hprof=cpu=samples,file=/home/test/java.hprof

試しにServlet中でforループをたくさん回した状態でhprofを実行してみる。sloweb.SlowServletが遅い原因としてCPU時間を使用していることが浮かび上がってくる。

CPU SAMPLES BEGIN (total = 35772) Tue Mar 11 20:36:15 2014
rank   self  accum   count trace method
   1 91.91% 91.91%   32878 301280 sun.nio.ch.KQueueArrayWrapper.kevent0
   2  2.47% 94.38%     882 300320 java.lang.ClassLoader.defineClass1
   3  1.05% 95.43%     376 301958 slowweb.SlowServlet.processRequest
   4  0.09% 95.52%      33 300506 java.io.FileInputStream.readBytes
   5  0.08% 95.60%      29 300043 java.util.zip.ZipFile.open

ヒープメモリが足りない(OutOfMemoryErrorの発生)

取得する情報

• GCログ
• クラスヒストグラム
• ヒープダンプ

データ取得方法

GCログ

GCログを取得して確認すると、ヒープメモリが足りなくなった原因が『ゆるやかな上昇』なのか『急激な上昇』が原因なのかがわかる。ゆるやかな上昇であった場合、オブジェクト参照の解放漏れなどが原因なので解析は少し厄介。急激な上昇が見られた場合は、多くの場合DBやファイルから一度に大量のデータを読み込んだことが良くある原因だろう。

GCログは以下のJava起動オプションに以下のように設定することで取得する。JDK6u34/JDK7u2からはサイズローテーション機能もあって便利。取得したGCログはGCViewerを使ってグラフ化する。

-Xloggc:/home/test/wildfly-8.0.0.Final/standalone/log/gc.log
-XX:+PrintGCDetails -XX:+PrintGCDateStamps
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M

取得先パス(-Xloggc)は、APサーバのログディレクトリに設定すると便利。

クラスヒストグラム

クラスヒストグラムを取得すると、ヒープを圧迫している原因クラスが見えてくる。後述するヒープダンプに比べ負荷が軽いの便利な点だが、取得に伴うFullGC発生には気をつける必要がある。スレッドダンプと同様、JDK7のjcmdの導入に伴い複数のやり方で取得することが可能。

• ${JAVA_HOME}/bin/jmap -histo:live <pid>
• ${JAVA_HOME}/bin/jcmd <pid> GC.class_histogram (JDK7〜)

起動中のNetBeansに向けて実行してみる。

 num     #instances         #bytes  class name
----------------------------------------------
   1:         25028       24122528  [B
   2:        203992       22519616  [C
   3:        199716        6390912  java.util.HashMap$Node

ヒープダンプ

クラスヒストグラムではオブジェクト間の参照関係までは確認できないので、誰が参照していてGCされないのかを調べることはできない。このような場合、テスト環境で問題を再現させてヒープダンプを取得する。それなりに重たいので、運用環境で実行することはお勧めできない。

ヒープダンプも同様に、複数のやり方で取得可能。

• ${JAVA_HOME}/bin/jmap -dump:live,format=b,file=dump.bin <pid>

• ${JAVA_HOME}/bin/jcmd <pid> GC.heap_dump

ヒープダンプの読み込みツールにはJDK標準のjhatもあるが、Eclipse Memory Analyzerが使いやすいと思う。

試しに動いているNetBeansを対象にヒープダンプを取得してEclipse Memory Analyzerに読み込ませてみると、以下のようにヒープ中に多いオブジェクトの指摘(Leak Suspects機能)などを確認できる。

まとめ

• アプリケーションから応答がない時はスレッドダンプ
• 遅いときはプロファイルとスレッドダンプ
• Javaヒープメモリが足りなくなったらGCログ/クラスヒストグラム/ヒープダンプ

もちろん、全ての問題がこれらの情報で解決できるわけではないが、初動対応として最低限あると便利な情報だと思う。

また、最近は有償のJava Flight RecorderやOSSのHeapStatsなど、システムが正常に動いているときから少しずつ情報を取得するツールも出てきている。またの機会にまとめる予定。