ページの先頭行へ戻る
Interstage Application Server V12.0.0 Java EE 7 設計・構築・運用ガイド
FUJITSU Software
第12章 トラブルシューティング > 12.11 スレッドダンプが出力された場合の対処
前次

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

スレッドダンプは、アプリケーション最大処理時間の超過時、プロセス起動時間・停止時間の超過時、または、生存通知の監視時間の超過時に出力されます。詳細は以下を参照してください。

「2.5.3 アプリケーション最大処理時間の監視」

「2.5.4 プロセスの起動時間監視・停止時間監視」

「2.5.5 生存通知の監視」

■出力例

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

"Java Thread dump tool" #160 prio=5 os_prio=15 tid=0x00000000590c5800 nid=0x11ac waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"p: admin-thread-pool; w: 10" #143 daemon prio=5 os_prio=0 tid=0x000000005934d000 nid=0x16f4 in Object.wait() [0x00000000650ef000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000f7396fe8> (a java.lang.Object)
	at com.sun.corba.ee.impl.threadpool.WorkQueueImpl.requestWork(WorkQueueImpl.java:124)
	- locked <0x00000000f97a0368> (a com.sun.corba.ee.impl.threadpool.WorkQueueImpl)
	at com.sun.corba.ee.impl.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:518)

 ・・・中略・・・

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000052a78800 nid=0x12d0 in Object.wait() [0x000000005385e000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x00000000e0081518> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000052a6f800 nid=0xc34 in Object.wait() [0x000000005399f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x00000000e00a6d00> (a java.lang.ref.Reference$Lock)

"VM Thread" os_prio=2 tid=0x0000000052a67800 nid=0x1420 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x000000000139b000 nid=0x146c runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x000000000139c800 nid=0x137c runnable

"VM Periodic Task Thread" os_prio=2 tid=0x0000000053cba800 nid=0x10bc waiting on condition

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

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

出力例
"http-listener-1(10)" #44 daemon prio=5 os_prio=0 tid=0x0000000054cc4000 nid=0x114c waiting on condition [0x000000005bacd000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at examples.TestServlet.doGet(TestServlet.java:15)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
   ・・・以下省略・・・

上記出力例では、TestServletのdoGetメソッドの15行目でsleepしていることがわかります(太字の部分)。

解析方法

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

スタックトレースの解析時には、「チューニングガイド」-「JDK/JRE 8のチューニング」-「チューニング/デバッグ技法」-「スレッドダンプ」もあわせて参照してください。

以下は調査対象となる代表的なスレッドのスタックトレースの出力例です。

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

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


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

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

"http-listener-1(14)" #48 daemon prio=5 os_prio=0 tid=0x0000000054cc7000 nid=0x1bc0 runnable [0x000000005c11d000]
   java.lang.Thread.State: RUNNABLE
	at samples.TestServlet.doGet(TestServlet.java:20)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:318)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
   ・・・以下省略・・・

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


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

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

"http-listener-1(7)" #41 daemon prio=5 os_prio=0 tid=0x0000000054cc2000 nid=0x15f4 waiting on condition [0x000000005b77d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at examples.TestTag.doEndTag(TestTag.java:41)
	at org.apache.jsp.test_jsp._jspx_meth_hello_sayHello_0(test_jsp.java:103)
	at org.apache.jsp.test_jsp._jspService(test_jsp.java:77)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:111)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:411)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:473)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:377)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
   ・・・以下省略・・・

上記出力例では、test.jspから呼び出されているカスタムタグTestTagのdoEndTagメソッドの41行目でsleepしていることがわかります(太字の部分)。


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

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

"http-listener-1(2)" #36 daemon prio=5 os_prio=0 tid=0x0000000054f74800 nid=0x1bb4 waiting on condition [0x000000005b1dd000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at examples.TestFilter2.doFilter(TestFilter2.java:27)      (2)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
	at examples.TestFilter1.doFilter(TestFilter1.java:23)      (1)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:256)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
   ・・・以下省略・・・

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

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

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

"ContainerBackgroundProcessor[StandardEngine[glassfish-web].StandardHost[server].StandardContext[/examples]]" #186 daemon prio=5 os_prio=0 tid=0x0000000054e96800 nid=0x1218 runnable [0x000000006770e000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestListener.sessionDestroyed(TestListener.java:25)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:910)
	- locked <0x00000000f5cf8048> (a org.apache.catalina.session.StandardSession)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:854)
	at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:771)
	at org.apache.catalina.session.StandardManager.processExpires(StandardManager.java:1056)
	at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:6340)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1823)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1812)
	at java.lang.Thread.run(Thread.java:745)

上記出力例ではTestListenerのsessionDestroyedメソッドの25行目が処理中であることがわかります(太字の部分)。

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

【Interstage Java EE 7 DASサービス、IJServerクラスタ起動時のスレッド】

Interstage Java EE 7 DASサービスやIJServerクラスタ起動時には、load-on-startupを指定したサーブレットのinit等が実行されます。

"RunLevelControllerThread-1456971526502" #15 daemon prio=5 os_prio=0 tid=0x0000000056f71800 nid=0x14ec runnable [0x00000000544dd000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.init(TestServlet.java:49)
	at javax.servlet.GenericServlet.init(GenericServlet.java:244)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1583)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1382)
	- locked <0x00000000f668b8f0> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5704)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:5946)
	- locked <0x00000000f664d228> (a com.sun.enterprise.web.WebModule)
   ・・・以下省略・・・

上記出力例ではTestServletのinitメソッドの49行目が処理中であることがわかります(太字の部分)。

【Interstage Java EE 7 DASサービス、IJServerクラスタ停止時のスレッド】

Interstage Java EE 7 DASサービスやIJServerクラスタの停止時には、サーブレットのdestroy等が実行されます。

"RunLevelControllerThread-1456972018436" #158 daemon prio=5 os_prio=0 tid=0x0000000060a4b000 nid=0x1a14 runnable [0x00000000683ae000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.destroy(TestServlet.java:67)
	at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1899)
	- locked <0x00000000f864b738> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardWrapper.stop(StandardWrapper.java:2194)
	at org.apache.catalina.core.StandardContext.stop(StandardContext.java:6121)
	- locked <0x00000000f863cd50> (a com.sun.enterprise.web.WebModule)
   ・・・以下省略・・・

上記出力例ではTestServletのdestroyメソッドの67行目が処理中であることがわかります(太字の部分)。

前次
Copyright 2017-2021 FUJITSU LIMITED