A.5 サーブレット・コンテナのfull thread dumpが出力された場合の対処

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

目次索引

A.5 サーブレット・コンテナのfull thread dumpが出力された場合の対処

■full thread dump自動採取機能

　full thread dump自動採取機能は、アプリケーションが応答しない場合やサーブレット・コンテナが停止しない場合に、サーブレット・コンテナのfull thread dumpを自動的に採取する機能です。
　full thread dumpは、サーブレット・ゲートウェイのタイムアウトの原因や、サーブレット・コンテナが強制停止された原因の調査に有効な資料となります。

　full thread dumpは、以下の契機で“サーブレット・コンテナの起動ログ”に出力されます。

アプリケーションが応答しない場合
以下の場合、サーブレット・ゲートウェイは“アプリケーションが応答しない”状態と判断し、サーブレット・コンテナ監視プロセスに対してfull thread dumpの採取を依頼します。
- サーブレット・コンテナへの処理要求がタイムアウトとなった場合
- サーブレット・コンテナからの情報返却待ちがタイムアウトとなった場合
サーブレット・コンテナが停止しない場合
jssvstopコマンドまたはjscontstopコマンド実行時に以下の状態となった場合、サーブレット・コンテナ監視プロセスは、“サーブレット・コンテナが停止しない”状態と判断し、full thread dumpを採取します。
- サーブレット・コンテナが停止要求を受け付けない
- 停止要求を受け付けたが、JServlet環境定義ファイルのcontainer.shutdownIntervalで指定された時間待っても終了しない(タイムアウト)

JServlet環境定義ファイルの定義項目[containername].logにfalseを設定した場合、full thread dumpは採取されません。
full thread dumpを自動採取するためには、JServlet環境定義ファイルの定義項目[containername].ipaddressと、サーブレット・ゲートウェイ環境定義ファイルの定義項目“Container”に同じIPアドレスまたは“localhost”を指定し、設定を統一させる必要があります。
サーブレット・コンテナの起動が完了するまでは、full thread dumpの自動採取は行われません。
jssvstopコマンドまたはjscontstopコマンド実行時に、full thread dump採取契機となっても、サーブレット・コンテナ起動から5分間はfull thread dumpの自動採取は行われません。
Webサーバとサーブレット・コンテナを分離したシステム構築で運用している場合、サーブレット・ゲートウェイのタイムアウト(アプリケーションが応答しない場合)を契機とするfull thread dumpの自動採取は行われません。
WebサーバにInterstage HTTP ServerまたはApache HTTP Serverを使用している場合には、サーブレット・ゲートウェイのタイムアウト(アプリケーションが応答しない場合)を契機とするfull thread dumpの自動採取は行われません。
サーブレット・コンテナの起動ログが10メガバイトを超えた場合、full thread dumpの自動採取は行われません。自動採取を再開するためには、当該サーブレット・コンテナを再起動してください。サーブレット・コンテナの起動ログは、再起動時にログのサイズが1メガバイトを超えていた場合、ファイル名に拡張子(.old)を付加してバックアップファイルを作成し、新規ログファイルにログを出力します。そのため、サーブレット・コンテナを再起動することで、full thread dumpの自動採取が可能になります。
運用上、すぐにサーブレット・コンテナの再起動ができない場合は、手動でfull thread dumpを採取することができます。この場合、サーブレット・コンテナの起動ログが10メガバイトを超えていても、full thread dumpは採取され、サーブレット・コンテナの起動ログに出力されます。
　<手動採取方法>
　　kill -QUIT [サーブレット・コンテナのプロセスID]

■出力形式

　各スレッドが走行していた場所がスタックトレース形式で出力されます。

■出力例

　以下に出力例を示します。
　注)表示の関係上、改行している箇所があるため、実際の出力形式とは若干の違いがあります。

*************************************************************************************
Full thread dump:

"Thread-19" prio=5 tid=0x29b50 nid=0x1 waiting on monitor [0..0xffbeeff8]

"MonitorRunnable" prio=5 tid=0x3adb28 nid=0x23 waiting on monitor [0xee281000..0xee281a28]
    at java.lang.Thread.sleep(Native Method)
    at com.fujitsu.interstage.jservlet.tomcat.util.ThreadPool$MonitorRunnable.run
        (ThreadPool.java:485)
    at java.lang.Thread.run(Thread.java:479)

"Thread-18" prio=5 tid=0x32e9b8 nid=0x22 waiting on monitor [0xee381000..0xee381a28]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:415)
    at com.fujitsu.interstage.jservlet.tomcat.util.ThreadPool$ControlRunnable.run
        (ThreadPool.java:601)
    at java.lang.Thread.run(Thread.java:479)

                        （中略）

"Thread-0" daemon prio=5 tid=0x3b03e0 nid=0xd waiting on monitor [0xef881000..0xef881a28]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:415)
    at com.fujitsu.interstage.jservlet.tomcat.util.Queue.pull(Queue.java:89)
    at com.fujitsu.interstage.jservlet.tomcat.logging.LogDaemon$1.run
        (TomcatLogger.java:274)
    at com.fujitsu.interstage.jservlet.tomcat.logging.LogDaemon.run
        (TomcatLogger.java:342)

"Signal Dispatcher" daemon prio=10 tid=0xe4490 nid=0xa waiting on monitor [0..0]

"Finalizer" daemon prio=8 tid=0xdf190 nid=0x7 waiting on monitor [0xfde81000..0xfde81a28]
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:157)

"Reference Handler" daemon prio=10 tid=0xdefd8 nid=0x6 waiting on monitor [0xfdf81000..0xfdf81a28]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:415)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:105)

"VM Thread" prio=5 tid=0xdeb70 nid=0x4 runnable 

"VM Periodic Task Thread" prio=10 tid=0xe32a0 nid=0x8 waiting on monitor 
"Suspend Checker Thread" prio=10 tid=0xe3b98 nid=0x9 runnable
*************************************************************************************

■full thread dumpの見方

　各スレッドの情報は、スタックトレースの見方と同じで、下から参照します。メソッドの呼び出し元から呼び出し先に向かって下から上にスタックに積まれ、現在走行中のメソッドが最上位に表示されます。

　注)表示の関係上、改行している箇所があるため、実際の出力形式とは若干の違いがあります。

[出力例]

*************************************************************************************
"Thread-18" prio=5 tid=0x2d9e28 nid=0x22 waiting on monitor [0xee380000..0xee381a28]
    at java.lang.Thread.sleep(Native Method)
    at com.fujitsu.jsp.SleepJSP$jsp._jspService(SleepJSP$jsp.java:66)     呼出し先
    at com.fujitsu.interstage.jservlet.jasper.runtime.HttpJspBase.service
        (HttpJspBase.java:138)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
    at com.fujitsu.interstage.jservlet.jasper.servlet.JspServlet$JspServletWrapper.
        service(JspServlet.java:322)
    at com.fujitsu.interstage.jservlet.jasper.servlet.JspServlet.serviceJspFile
        (JspServlet.java:507)
    at com.fujitsu.interstage.jservlet.jasper.servlet.JspServlet.service
        (JspServlet.java:694)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)       呼出し元
*************************************************************************************

[解析方法]

　スタックトレース中にアプリケーション開発者の作成したクラスがあれば、意図していないにもかかわらず、待ち状態になっていないか確認してください。行番号が表示されている場合は、ソースコードの参照によって、実行中の処理を確認できます。

　以下に代表的なスレッドのスタックトレースを説明します。

調査の対象となるスレッドのスタックトレース

通常、調査する必要のないスレッドのスタックトレース
- 接続待ちスレッド
- 割り当て待ちスレッド

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

　javax.servlet.http.HttpServletクラスserviceメソッドより上位のスタックが調査対象になります。このスレッドからは、通常のjavaクラスやEJBクライアントスタブ等が呼び出されます。

*************************************************************************************
"Thread-18" prio=5 tid=0x14e2b0 nid=0x21 waiting on monitor [0xee480000..0xee481a28]
    at java.lang.Thread.sleep(Native Method)
    at Sleep1minServlet.service(Sleep1minServlet.java:25)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
    at com.fujitsu.interstage.jservlet.tomcat.core.ServletWrapper.handleRequest
        (ServletWrapper.java:928)
    at com.fujitsu.interstage.jservlet.tomcat.core.ServletWrapper.handleRequest
        (ServletWrapper.java:1052)
                             以下省略
*************************************************************************************

◆JSP処理中のスレッド

　_jspServiceメソッドより上位のスタックが調査対象になります。このスレッドからは、スクリプトレット部分から呼び出されるjavaクラスやカスタムタグクラス等が呼び出されます。

*************************************************************************************
"Thread-18" prio=5 tid=0x2d9e28 nid=0x22 waiting on monitor [0xee380000..0xee381a28]
    at java.lang.Thread.sleep(Native Method)
    at com.fujitsu.jsp.SleepJSP$jsp._jspService(SleepJSP$jsp.java:66)
    at com.fujitsu.interstage.jservlet.jasper.runtime.HttpJspBase.service
        (HttpJspBase.java:138)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
    at com.fujitsu.interstage.jservlet.jasper.servlet.JspServlet$JspServletWrapper.
        service(JspServlet.java:322)
*************************************************************************************

◆フィルタ処理中のスレッド

　com.fujitsu.interstage.jservlet.tomcat.core.ApplicationFilterChainクラスdoFilterメソッドより上位のスタックが調査対象になります。このスレッドからは、以下のように次のフィルタを呼び出したり、また、最終的にサーブレット、JSP、静的コンテンツ等を呼び出したりします。

*************************************************************************************
"Thread-18" prio=5 tid=0x285e68 nid=0x22 waiting on monitor [0xee381000..0xee381a28]
    at java.lang.Thread.sleep(Native Method)
    at test.Filter01.doFilter(Filter01.java:19)
    at com.fujitsu.interstage.jservlet.tomcat.core.ApplicationFilterChain.doFilter
        (ApplicationFilterChain.java:210)
    at test.Filter02.doFilter(Filter02.java:15)
    at com.fujitsu.interstage.jservlet.tomcat.core.ApplicationFilterChain.doFilter
        (ApplicationFilterChain.java:210)
    at com.fujitsu.interstage.jservlet.tomcat.core.ApplicationFilterChain.doFilter
        (ApplicationFilterChain.java:158)
                             以下省略
*************************************************************************************

◆セッション監視スレッド

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

*************************************************************************************
"StandardManager" daemon prio=5 tid=0x1e6608 nid=0xf waiting on monitor [0xef681000..0xef681a28]
    at java.lang.Thread.sleep(Native Method)
    at test.TestSession.valueUnbound(TestSession.java:34)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardSession.
        attributeValueUnboundEvent(StandardSession.java:880)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardSession.
            removeAttribute(StandardSession.java:847)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardSession.
        expireCore(StandardSession.java:471)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardSession.
        expire(StandardSession.java:430)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardManager.
        processExpires(StandardManager.java:420)
    at com.fujitsu.interstage.jservlet.tomcat.session.StandardManager.
        run(StandardManager.java:490)
    at java.lang.Thread.run(Thread.java:479)
*************************************************************************************

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

◆接続待ちスレッド

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

*************************************************************************************
"Thread-17" prio=5 tid=0x14d970 nid=0x20 runnable [0xee581000..0xee581a28]
    at java.net.PlainSocketImpl.socketAccept(Native Method)
    at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:463)
    at java.net.ServerSocket.implAccept(ServerSocket.java:238)
    at java.net.ServerSocket.accept(ServerSocket.java:217)
                            以下省略
*************************************************************************************

◆割り当て待ちスレッド

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

*************************************************************************************
"Thread-16" prio=5 tid=0x14d030 nid=0x1f waiting on monitor [0xee681000..0xee681a28]
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:415)
    at com.fujitsu.interstage.jservlet.tomcat.util.ThreadPool$ControlRunnable.run
        (ThreadPool.java:601)
    at java.lang.Thread.run(Thread.java:479)
*************************************************************************************

目次索引