検索
連載

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

本連載は、日立製作所が提供するアプリケーションサーバ「Cosminexus」の開発担当者へのインタビューを通じて、Webシステムにおける、さまざまな問題／トラブルの解決に効くノウハウや注意点を紹介していく。現在起きている問題の解決や、今後の開発のご参考に（編集部）

Share
Tweet
LINE
Hatena
前のページへ | 　　　　　　

スレッドダンプの解析

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

【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の処理を実行しています。無限ループに陥っている可能性がある。

早期の問題解決には、推定原因から詳細原因を探れ

　今回は、Java EEサーバでプロセスハングアップが発生した場合の問題解決の手順と、ログ・トレース、スレッドダンプの解析のポイントについて説明した。推定原因を定め、その情報を元に詳細原因を探ることで早期の原因特定が可能になるということだ。

「次回」へ


「現場にキく、Webシステムの問題解決ノウハウ」バックナンバー

Copyright © ITmedia, Inc. All Rights Reserved.

前のページへ | 　　　　　　
ページトップに戻る