Java EEサーバからレスポンス返らず。何から調べる？：現場にキく、Webシステムの問題解決ノウハウ（1）（2/2 ページ）

» 2009年11月26日 00時00分公開

[＠IT編集部，＠IT]

前のページへ 1|2 　　　　　　

スレッドダンプの解析

　スレッドダンプの解析では、障害の推定原因に応じて解析方法が異なる。それぞれの推定原因に応じた解析方法について説明しよう。

【1】バックプロセス無応答

　バックプロセス無応答の疑いがある場合には、スレッドダンプを複数回取得しておき、時系列で観察して同一スレッドIDでの比較調査を行う。調査のポイントは、次の3つだ。

【調査のポイント】

バックプロセス応答待ちスレッドのスレッド属性はrunnable（実行中）
複数のスレッドダンプで属性が常にrunnableのスレッドIDを探す
上記IDのスレッドが複数のスレッドダンプで同じ場所を実行している

　これらの特徴を持つスレッドを見つけ出し、どこでハングアップしているかを調べる。下記にスレッドダンプの例を示そう。

"Thread-1" prio=9 tid=0x54c3a70 nid=723 runnable [0x4ff27000..0x4ff27438]
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.send (Native Method)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.sendData(JdbcDbpsvLib.java:311)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvResultSQLExecute.SQLGetResult(JdbcDbpsvResultSQLExecute.java:1488) 
 
　　　　　　　　　　【略】

スレッドダンプ1

"Thread-1" prio=9 tid=0x54c3a70 nid=723 runnable [0x4ff27000..0x4ff27438]
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.send (Native Method)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.sendData(JdbcDbpsvLib.java:311)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvResultSQLExecute.SQLGetResult(JdbcDbpsvResultSQLExecute.java:1488) 
 
　　　　　　　　　　【略】

スレッドダンプ2

"Thread-1" prio=9 tid=0x54c3a70 nid=723 runnable [0x4ff27000..0x4ff27438]
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.send (Native Method)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvLib.sendData(JdbcDbpsvLib.java:311)
　　　　　　　　　　at JP.co.Hitachi.soft.DBPSV_Driver.JdbcDbpsvResultSQLExecute.SQLGetResult(JdbcDbpsvResultSQLExecute.java:1488) 
 
　　　　　　　　　　【略】

スレッドダンプ3

【解析のポイント】

　スレッドダンプを複数回取得して、時系列で観察し、同じスレッドIDのスタックトレースを比較調査する。

ポイント【1】：runnable
スレッド属性がrunnableな場合、このスレッドは実行可能状態にある。このようなスレッドを対象に調査する（「waiting for monitor entry」の場合は実行可能状態ではないため、CPU利用率を増加させない）
ポイント【2】：tid=0x54c3a70
複数のスレッドダンプで、同一のスレッドIDの属性がすべてrunnableである。長時間にわたって実行中となっている可能性がある
ポイント【3】：Native Method
複数のスレッドダンプで、同一のスレッドIDがすべて同じ場所を実行中である

　上記の例では、Native Method実行の応答が返ってこないためハングアップが発生している。この場合、「tid=0x54c3a70」のスレッドが複数のスレッドダンプで同じ場所を実行中となっていて、このスレッドがデータベースからの応答を待っているため、ハングアップが発生していると分かる。

【2】デッドロック

　デッドロックの疑いがある場合には、スレッドが取得しているロックオブジェクトの関係に着目して解析する。デッドロックを調査する場合のポイントは、次の3つだ。

【調査のポイント】

スレッド属性がrunnnableのスレッドは除外してよい
ロック取得待ちの場合、スレッドの属性は「waiting for monitor entry」
スレッドダンプには、取得済みロックオブジェクトの情報が記載される。取得待ちしているロックオブジェクトがほかのスレッドで取得済みになっている場合、デッドロックの可能性が高い。互いにロックを取り合っていないかを確認

　デッドロックの場合のスレッドダンプの例を以下に示そう。

"Thread-5" prio=5 tid=0x0096A4B8 nid=0x40c runnable [af8f000..af8fdb4]
        at deadlock.run(deadlock.java:48)
 
"Thread-3" prio=5 tid=0x008FEFB0 nid=0x5b0 waiting for monitor entry [af0f000..af0fdb4]
        at deadlock.run(deadlock.java:42)
        - waiting to lock <02A328C0> (a java.lang.Object)
        - locked <02A328C8> (a java.lang.Object)
 
"Thread-1" prio=5 tid=0x00900220 nid=0x234 waiting for monitor entry [ae8f000..ae8fdb4]
        at deadlock.run(deadlock.java:33)
        - waiting to lock <02A328C8> (a java.lang.Object)
        - locked <02A328C0> (a java.lang.Object)

【解析のポイント】

ポイント【1】：runnable
スレッド属性がrunnableである場合、このスレッドは実行可能状態にある。このようなスレッドはデッドロックとは無関係
ポイント【2】：waiting for monitor entry
スレッド属性が「waiting for monitor entry」である場合、スレッドはロックの取得待ちであることを示している。デッドロックを起こしているスレッドである可能性がある
ポイント【3】：02A328C8
スレッドがロックを取得しており、かつポイント2でスレッドのロック取得待ちである場合、デッドロックを起こしているスレッドである可能性がさらに高い

　ポイント2、3に当てはまるスレッドに対し、ロックしているオブジェクトのアドレスをつき合わせながらデッドロックを検出する。上記の場合、Thread-3は、<02A328C8>のロックを取得して、かつ<02A328C0>の取得待ちを示している。一方、Thread-1は、<02A328C0>のロックを取得していて、かつ<02A328C8>の取得待ちとなっていて、Thread-3とThread-1がデッドロックしていることが分かる。

　なお、「バックプロセス無応答の原因がJavaと外部リソースの間でのロックの掛け合いである」というケースもある。この場合は、外部リソース側のロックはスレッドダンプには現れないので注意が必要だ。

【3】無限ループ

　無限ループの疑いがある場合も、スレッドダンプを複数回取得しておき、時系列で同一スレッドIDに対して比較調査を行う。調査のポイントは、次の3つだ。

【調査のポイント】

無限ループを起こしているスレッドのスレッド属性はrunnable
複数のスレッドダンプファイルで属性が常にrunnableのスレッドIDを探す
上記IDのスレッドが、同一メソッドの特定の行を繰り返し実行している

　以下に、無限ループの場合のスレッドダンプファイルの例を示すので、これらの特徴を持つスレッドを見つけ出し、どこで無限ループに陥っているかを調べてみよう。

"Ajp13Processor[8007][80]"  daemon prio=1 tid=0x312d5ee8 nid=0x1b24 runnable [317ab000..317ad560]
    at java.security.AccessController.doPrivileged(Native Method)
    at org.apache.catalina.connector.HttpRequestBase.getSession(HttpRequestBase.java:1186)
    at org.apache.catalina.connector.HttpRequestFacade.getSession(HttpRequestFacade.java:209)
    at org.apache.catalina.connector.HttpRequestFacade.getSession(HttpRequestFacade.java:218)
    at org.apache.jsp.Jsp1$jsp._jspService(Jsp1$jsp.java:62)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:108)
 
    【略】

スレッドダンプ1

"Ajp13Processor[8007][80]"  daemon prio=1 tid=0x312d5ee8 nid=0x1b24 runnable [317ab000..317ad560]
    at org.apache.catalina.session.StandardSession.setAttribute(StandardSession.java:1207)
    at org.apache.catalina.session.StandardSessionFacade.setAttribute(StandardSessionFacade.java:191)
    at org.apache.catalina.session.StandardSessionFacade.setAttribute(StandardSessionFacade.java:191)
    at org.apache.jsp.Jsp1$jsp._jspService(Jsp1$jsp.java:62)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:108)
 
    【略】

スレッドダンプ2

"Ajp13Processor[8007][80]"  daemon prio=1 tid=0x312d5ee8 nid=0x1b24 runnable [317ab000..317ad560]
    at org.apache.catalina.session.StandardSession.setAttribute(StandardSession.java:1207)
    at org.apache.catalina.session.StandardSessionFacade.setAttribute(StandardSessionFacade.java:191)
    at org.apache.catalina.session.StandardSessionFacade.setAttribute(StandardSessionFacade.java:191)
    at org.apache.jsp.Jsp1$jsp._jspService(Jsp1$jsp.java:62)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:108)
 
    【略】

スレッドダンプ3

【解析のポイント】

　スレッドダンプを複数回取得して、時系列で観察し、同じスレッドIDのスタックトレースを比較調査する。

ポイント【1】：runnable
スレッド属性がrunnableな場合、このスレッドは実行可能状態にある。このようなスレッドを対象に調査する（「waiting for monitor entry」である場合はCPU利用率を増加させない）
ポイント【2】：tid=0x312d5ee8
複数のスレッドダンプで、同一のスレッドIDの属性がすべてrunnableである。長時間にわたって実行中となっている可能性がある
ポイント【3】：Jsp1$jsp.java:62
同一メソッド内の特定の範囲の行が複数回繰り返して実行されているような場合、無限ループの疑いがある

　この場合、「tid=0x312d5ee8」のスレッドは、複数のスレッドダンプでJsp1$jsp.java:62の処理を実行しています。無限ループに陥っている可能性がある。