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

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

目次索引

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

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

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

■出力例

　以下にスタックトレース部の出力例を示します。

[出力例]

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

[出力例]

  *******************************************************************************
  "http-9000-Processor15" daemon prio=6 tid=0x287b7008 nid=0x111c waiting on condition [0x05ebf000..0x05ebfa98]
  at java.lang.Thread.sleep(Native Method)
  at examples.TestServlet.doGet(Test.java:12)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
  *******************************************************************************

　上記出力例では、TestServletのdoGetメソッドの12行目でsleepしていることがわかります。

[解析方法]

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

　スタックトレースの解析時には“チューニングガイド”の“スレッドダンプ”もあわせて参照してください。
　以下は調査対象となる代表的なスレッドのスタックトレースの出力例です。

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

　リクエスト処理中のスレッドではフィルター/サーブレット/JSP等が処理されます。

サーブレット処理中のスレッドの出力例

　サーブレットの場合はdoGetやdoPost等、オーバーライドして作成したサーブレットのメソッドより上位のスタックが調査対象となります。

  *******************************************************************************
  "http-9000-Processor15" daemon prio=6 tid=0x56ae0070 nid=0x11c8 runnable [0x5f58f000..0x5f58fb98]
  at examples.TestServlet.doGet(TestServlet.java:27)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
                             以下省略
  *******************************************************************************

　上記出力例ではTestServletのdoGetメソッドより上位のスタックが調査対象となります。
　ここではTestServletのdoGetメソッドが処理中であることがわかります。

JSP処理中のスレッドの出力例

　JSPの場合は以下のようにorg.apache.jspから始まるパッケージ名のクラスに変換されています。通常HttpJspBaseのserviceメソッドより上位のスタックが調査対象となります。このスレッドからは、スクリプトレット部分から呼び出されるjavaクラスやカスタムタグクラス等が呼び出されます。

  *******************************************************************************
  "http-9000-Processor16" daemon prio=6 tid=0x5688f7b8 nid=0x10c8 waiting on condition [0x619af000..0x619afa98]
  at java.lang.Thread.sleep(Native Method)
  at examples.TestTag.doEndTag(TestTag.java:19)
  at org.apache.jsp.jsp.test_jsp._jspService(test_jsp.java:64)
  at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:97)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
  at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:373)
  at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:329)
  at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:271)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
                             以下省略
  *******************************************************************************

　上記出力例ではカスタムタグTestTagのdoEndTagメソッドの19行でsleepしていることがわかります。

フィルター処理中のスレッドの出力例

　フィルターの場合はオーバーライドして作成したdoFilterメソッドより上位のスタックが調査対象となります。

  *******************************************************************************
  "http-9000-Processor16" daemon prio=6 tid=0x56a5a050 nid=0x1230 waiting on condition [0x6174f000..0x6174fb98]
  at java.lang.Thread.sleep(Native Method)
  at examples.TestFilter2.doFilter(TestFilter2.java:15)     (2)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
  at examples.TestFilter1.doFilter(TestFilter1.java:18)      (1)
  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
                             以下省略
  *******************************************************************************

　上記出力例ではフィルターが2つ定義されているため(1)と(2)の2箇所に作成したフィルターのスタックが出力されており、TestFilter1、TestFilter2の順番で呼び出されTestFilter2のdoFilterメソッドの15行でsleepしていることがわかります。

【サーブレットのセションタイムアウト時のスレッド】

　サーブレットのセションタイムアウト時のスレッドではHttpSessionListenerのsessionDestroyed等のセションが破棄された場合の処理が動作します。

  *******************************************************************************
  "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x569bbfa0 nid=0x111c runnable  [0x60fcf000..0x60fcfb98]
  at examples.TestListener.sessionDestroyed(TestListener.java:45)
  at org.apache.catalina.session.StandardSession.expire(StandardSession.java:701)
  - locked <0x4dc9abe8> (a com.fujitsu.interstage.jservlet.catalina.session.ISSession)
  at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:581)
  - locked <0x4e7e3e80> (a com.fujitsu.interstage.jservlet.catalina.session.ISManager)
  at org.apache.catalina.session.ManagerBase.processExpires(ManagerBase.java:678)
  at org.apache.catalina.session.ManagerBase.backgroundProcess(ManagerBase.java:663)
  at com.fujitsu.interstage.jservlet.catalina.session.ISManager.backgroundProcess(ISManager.java:147)
  at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1284)
  at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1569)
  at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1578)
  at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1578)
  at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1558)
  at java.lang.Thread.run(Thread.java:595)
                             以下省略
  *******************************************************************************

　上記出力例ではTestListenerのsessionDestroyedメソッドの45行が処理中であることがわかります。

　※セションのタイムアウト時に呼び出される処理はスレッドダンプ自動採取の対象外です。

【IJServer起動時のスレッド】

　IJServer起動時にはload-on-startupを指定したサーブレットの初期化等が実行されます。

  *******************************************************************************
  "main" prio=6 tid=0x0028cc08 nid=0x1080 runnable [0x0006f000..0x0006fbf8]
  at examples.TestServlet.init(TestServlet.java:26)
  at javax.servlet.GenericServlet.init(GenericServlet.java:211)
  at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1105)
  - locked <0x4cfccef0> (a org.apache.catalina.core.StandardWrapper)
  at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:932)
  - locked <0x4cfccef0> (a org.apache.catalina.core.StandardWrapper)
  at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:3952)
  at com.fujitsu.interstage.jservlet.catalina.core.ISContext.loadOnStartup(ISContext.java:324)
  at org.apache.catalina.core.StandardContext.start(StandardContext.java:4226)
  - locked <0x4e8f1c70> (a com.fujitsu.interstage.jservlet.catalina.core.ISContext)
  at com.fujitsu.interstage.jservlet.catalina.core.ISContext.start(ISContext.java:140)
  - locked <0x4e8f1c70> (a com.fujitsu.interstage.jservlet.catalina.core.ISContext)
                             中略
  at com.fujitsu.interstage.j2ee.ijserver.startup.IJServerBoot.process(IJServerBoot.java:532)
  at com.fujitsu.interstage.j2ee.ijserver.startup.IJServerBoot.start(IJServerBoot.java:588)
  at com.fujitsu.interstage.j2ee.ijserver.startup.IJServerBoot.main(IJServerBoot.java:199)
  *******************************************************************************

　上記出力例ではTestServletのinitメソッドの26行が処理中であることがわかります。

【IJServer停止時のスレッド】

　IJServer停止時のスレッドではサーブレットのdestroy等が処理されます。

  *******************************************************************************
  "Thread-29" prio=6 tid=0x613d62b0 nid=0x11c4 runnable [0x6617f000..0x6617fb18]
  at examples.TestServlet.destroy(TestServlet.java:38)
  at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1326)
  - locked <0x4e866370> (a org.apache.catalina.core.StandardWrapper)
  at org.apache.catalina.core.StandardWrapper.stop(StandardWrapper.java:1654)
  at org.apache.catalina.core.StandardContext.stop(StandardContext.java:4346)
  - locked <0x4e85e728> (a com.fujitsu.interstage.jservlet.catalina.core.ISContext)
  at com.fujitsu.interstage.jservlet.catalina.core.ISContext.stop(ISContext.java:117)
  - locked <0x4e85e728> (a com.fujitsu.interstage.jservlet.catalina.core.ISContext)
                             中略
  at com.fujitsu.interstage.j2ee.ijserver.context.IJServerContext.stop(IJServerContext.java:536)
  at com.fujitsu.interstage.j2ee.ijserver.core.ISServer.syncStop(ISServer.java:943)
  at com.fujitsu.interstage.j2ee.ijserver.core.ISServer$1.run(ISServer.java:648)
  *******************************************************************************

　上記出力例ではTestServletのdestroyメソッドの38行が処理中であることがわかります。

目次索引