9.9 スレッドダンプが出力された場合の対処

Interstage Application Server トラブルシューティング集

目次索引

第9章 J2EEアプリケーション開発・運用時の異常

9.9 スレッドダンプが出力された場合の対処

　スレッドダンプは、以下の契機でコンテナ情報ログ(info.log)に出力されます。

起動時のタイムアウト
アプリケーションのタイムアウト
停止時のタイムアウト

　スレッドダンプ出力については、“J2EE ユーザーズガイド”の“スレッドダンプ自動採取”を参照してください。

■出力形式

　スレッドダンプの出力形式について説明します。スレッドダンプは、以下の３つの部分から構成されます。各部分の境界には、“*”の連続が出力され区切りを表します。

ヘッダ部
スレッドダンプの始まりを示します。Javaプロセスの情報が出力されます。
各スレッドのスタックトレース部
ダンプ採取時、各スレッドが走行していた場所がスタックトレース形式で出力されます。
フッタ部
スレッドダンプの終了を示します。

■出力例

　以下に出力例を示します。

[出力例]

  *******************************************************************************
   Java Thread dump Tool for WindowsNT/2000/XP 
   Copyright(c) 2002 FUJITSU LIMITED. All rights reserved.
    start at Fri Aug 01 14:36:45 2003
    cmd = "D:\Interstage\JDK13\bin\java.exe"  -Xrs -Xrunfmoni:detail=y
          -XX:+JavaMonitorsInStackTrace
                         （中略）
    Memory usage (Free/Total) = 18322472/24510464 (bytes)
   (ProcessId = 0xee8, Tool ThreadId = 0x11e4)
  *******************************************************************************
  Full thread dump:
  
  "Thread-29" prio=10 tid=0x12a23d50 nid=0x11e4 waiting on monitor [0..0x1ef4fd6c]
  "RMI LeaseChecker" daemon prio=5 tid=0x14831c18 nid=0x1270 waiting on monitor
      [0x1d7ff000..0x1d7ffdf8]
        at java.lang.Thread.sleep(Native Method)
        at sun.rmi.transport.DGCImpl$LeaseChecker.run(DGCImpl.java:294)
        at java.lang.Thread.run(Thread.java:479)
  "RMI Reaper" prio=5 tid=0x12f46020 nid=0x11f0 waiting on monitor
      [0x1d77f000..0x1d77fdf8]
        at java.lang.Object.wait(Native Method)
                          （中略）
  "main" prio=5 tid=0x287d00 nid=0x1148 runnable [0x6f000..0x6fc20]
        at com.fujitsu.interstage.j2ee.ijserver.util.WUties.extp_is_IJServer_stop
          (Native Method)
        at com.fujitsu.interstage.j2ee.ijserver.util.WUties.stop(WUties.java:220)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:664)
        at org.apache.catalina.startup.Catalina.execute(Catalina.java:442)
        at org.apache.catalina.startup.Catalina.process(Catalina.java:207)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.fujitsu.interstage.j2ee.ijserver.IJServer.main(IJServer.java:407)
  "VM Thread" prio=5 tid=0x7184d0 nid=0x1150 runnable
  "VM Periodic Task Thread" prio=10 tid=0x71ac60 nid=0x11c0 waiting on monitor
  "Suspend Checker Thread" prio=10 tid=0x71b620 nid=0xeac runnable
  *******************************************************************************
   Java Thread dump end
  *******************************************************************************

■スタックトレースの見方

　スタックトレースは、javaのjava.lang.ThrowableクラスprintStackTraceメソッドが出力する形式と同様です。メソッドの呼び出し元から呼び出し先に向かって下から上にスタックに積まれ、現在走行中のメソッドが最上位に表示されます。

[出力例]

  *******************************************************************************
  "Thread-20" daemon prio=5 tid=0x12a31cd8 nid=0x1030 waiting on monitor   [0x1d6bf000..0x1d6bfdf8]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.jsp.testjsp_jsp._jspService(testjsp_jsp.java:84)                 呼出し先
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:210)             ↑
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)                    ↑
    at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:300) ↑
    at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:324)        ↑
    at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:244)               ↑
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)                呼出し元
  *******************************************************************************

[解析方法]

　スタックトレース中に自分で作成したクラスがあれば、意図せずに待ち状態になっていないか確認してください。行番号が表示されている場合は、ソースコードを参照することで実行中の処理を確認することができます。

　以下に調査対象となる代表的なスレッドのスタックトレースを説明します。

【サーブレット処理中のスレッド】

　javax.servlet.http.HttpServletクラスserviceメソッドより、上位のスタックがWebアプリケーションで実装したサーブレットクラスになります。この部分の実行スタックが調査対象になります。このスレッドからは、通常のjavaクラスやEJBクライアントスタブ等が呼び出されます。

  *******************************************************************************
  "Thread-20" daemon prio=5 tid=0x6d2358 nid=0x1110 waiting on monitor [0x1dedf000..0x1dedfdf8]
    at java.lang.Thread.sleep(Native Method)
    at test.HelloWorldServlet.service(HelloWorldServlet.java:27)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:478)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:250)
                             以下省略
  *******************************************************************************

【JSP処理中のスレッド】

　org.apatch.jsp.[JSPファイル名から生成されるクラス名]がJSPから自動生成されるクラスです。このクラスより上位の実行スタックが調査対象になります。このスレッドからは、スクリプトレット部分から呼び出されるjavaクラスやカスタムタグクラス等が呼び出されます。

  *******************************************************************************
  "Thread-19" daemon prio=5 tid=0x12e8f4f8 nid=0x11b8 waiting on monitor   [0x1ea0f000..0x1ea0fdf8]
    at java.lang.Thread.sleep(Native Method)
    at org.apache.jsp.testjsp_jsp._jspService(testjsp_jsp.java:84)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:210)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
    at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:300)
                             以下省略
  *******************************************************************************

【フィルター処理中のスレッド】

　org.apache.catalina.core.ApplicationFilterChainクラスinternalDoFilterメソッドより上位がWebアプリケーションで実装したフィルタークラスになります。この部分の実行スタックが調査対象になります。このスレッドからは、以下のように次のフィルターを呼び出したりまた最終的にサーブレット、JSP、静的コンテンツ等を呼び出したりします。

  *******************************************************************************
  "Thread-19" daemon prio=5 tid=0x12f0e7c0 nid=0xfe8 waiting on monitor [0x1de9f000..0x1de9fdf8]
    at java.lang.Thread.sleep(Native Method)
    at test.Filter01.doFilter(Filter01.java:19)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:272)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:203)
    at test.Filter02.doFilter(Filter02.java:15)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:360)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:250)
                             以下省略
  *******************************************************************************

【セッション監視スレッド】

　Webアプリケーションごとに存在し、セッションのタイムアウト監視を行うスレッドです。タイムアウト検出時には、セッションオブジェクト(以下の例では、HttpSessionBindingListenerインタフェースをインプリメントしたtest.TestSessionクラス)にタイムアウトが通知されます。

  *******************************************************************************
  "StandardManager[/testWar]" daemon prio=5 tid=0x129e0920 nid=0x6ac waiting on monitor [0x1dabf000..0x1dabfdf8]
    at java.lang.Thread.sleep(Native Method)
    at test.TestSession.valueUnbound(TestSession.java:34)
    at org.apache.catalina.session.StandardSession.removeAttribute(StandardSession.java:1155)
    at org.apache.catalina.session.StandardSession.expire(StandardSession.java:635)
    at org.apache.catalina.session.StandardSession.expire(StandardSession.java:608)
    at org.apache.catalina.session.StandardManager.processExpires(StandardManager.java:806)
    at org.apache.catalina.session.StandardManager.run(StandardManager.java:883)
    at java.lang.Thread.run(Thread.java:479)
  *******************************************************************************

　上記の他にもWebアプリケーション実装部分としては、ServletContextListener、HttpSessionListener等のリスナに登録されたオブジェクトがあります。スタックトレースに現れたWebアプリケーション実装部分の動作や、複数スレッドの協調関係を調べることで異常原因を調べることができます。

　通常調査の必要はありませんが、他にもServletサービスが内部的に生成する多くのスタックトレースがスレッドダンプには出力されます。代表的なスレッドを説明します。

【接続待ちスレッド】

　ブラウザからのリクエストを待ち受けるスレッドです。リクエスト受付後サーブレット、JSP等のアプリ実装部が呼び出されます。

  *******************************************************************************
  "Thread-18" daemon prio=5 tid=0x12e8eab0 nid=0x10b0 runnable [0x1e9cf000..0x1e9cfdf8]
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:463)
    - locked <ac72e28> (a java.net.PlainSocketImpl)
    at java.net.ServerSocket.implAccept(ServerSocket.java:238)
    at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept([DashoPro-V1.2-120198])
                            以下省略
  *******************************************************************************

【割り当て待ちスレッド】

　接続待ちになる前のスレッドで複数存在します。接続待ちスレッドがリクエストを受け付けた後、任意の１つが接続待ちスレッドに割り当てられます。

  *******************************************************************************
  "Thread-17" daemon prio=5 tid=0x6a1688 nid=0x11a0 waiting on monitor [0x1e98f000..0x1e98fdf8]
    at java.lang.Object.wait(Native Method)
    - waiting on <ac74430> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
    at java.lang.Object.wait(Object.java:415)
    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:595)
    - locked <ac74430> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
    at java.lang.Thread.run(Thread.java:479)
  *******************************************************************************

目次索引