ページの先頭行へ戻る
Interstage Application Server/Interstage Web Server Express トラブルシューティング集
FUJITSU Software
第10章 Java EE使用時の異常 > 10.9 スレッドダンプが出力された場合の対処
前次

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

スレッドダンプは、アプリケーション最大処理時間の超過時や、IJServerクラスタ起動時・強制停止時のタイムアウト発生時に出力されます。詳細は「Java EE運用ガイド」の以下を参照してください。

■出力例

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

"Java Thread dump tool" prio=10 tid=0x0000000006654000 nid=0x18ec waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Thread-127" daemon prio=6 tid=0x0000000006653800 nid=0x1130 in Object.wait() [0x00000000088ff000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000fae25e18> (a com.sun.appserv.management.util.jmx.NotificationEmitterSupport$SenderThread)
	at com.sun.appserv.management.util.jmx.NotificationEmitterSupport$SenderThread.run(NotificationEmitterSupport.java:414)
	- locked <0x00000000fae25e18> (a com.sun.appserv.management.util.jmx.NotificationEmitterSupport$SenderThread)
   ・・・中略・・・

"Finalizer" daemon prio=8 tid=0x00000000014fe000 nid=0xfe4 in Object.wait() [0x000000000648f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000f000bf00> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
	- locked <0x00000000f000bf00> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00000000014f5000 nid=0xfe8 in Object.wait() [0x000000000638f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000f000bf30> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:485)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <0x00000000f000bf30> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x00000000014e7000 nid=0xe04 runnable 

"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000001439000 nid=0x17c8 runnable 

"GC task thread#1 (ParallelGC)" prio=6 tid=0x000000000143a800 nid=0x1458 runnable 

"VM Periodic Task Thread" prio=10 tid=0x0000000006505800 nid=0xe74 waiting on condition 

"RAS Control Thread" prio=10 tid=0x00000000014e4800 nid=0xfdc runnable

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

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

出力例
"httpWorkerThread-28090-2" daemon prio=6 tid=0x000000000984e800 nid=0x108c waiting on condition [0x000000000d58e000]
   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:734)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
   ・・・以下省略・・・

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

解析方法

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

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

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

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

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


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

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

"httpWorkerThread-28090-9" daemon prio=6 tid=0x0000000009f9c800 nid=0xef8 runnable [0x000000000ebbe000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.doGet(TestServlet.java:36)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:734)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
	at org.apache.catalina.core.ApplicationFilterChain.servletService(ApplicationFilterChain.java:427)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:333)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
   ・・・以下省略・・・

上記出力例ではTestServletのdoGetメソッドより上位のスタックが調査対象となります。

ここではTestServletのdoGetメソッドが処理中であることがわかります(太字の部分)。


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

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

"httpWorkerThread-28090-10" daemon prio=6 tid=0x000000000be66000 nid=0x1790 waiting on condition [0x000000000edce000]
   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 from :102)
	at org.apache.jsp.test_jsp._jspService(test_jsp.java from :77)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:109)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
	at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:426)
	at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:486)
	at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:380)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847)
   ・・・以下省略・・・

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


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

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

"httpWorkerThread-28090-0" daemon prio=6 tid=0x000000000984d000 nid=0x11bc waiting on condition [0x000000000d38e000]
   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:246)
	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:246)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
   ・・・以下省略・・・

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

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

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

"ContainerBackgroundProcessor[StandardEngine[com.sun.appserv].StandardHost[server].StandardContext[/examples]]" daemon prio=6 tid=0x000000000d7e4800 nid=0x1844 runnable [0x000000000d10f000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestListener.sessionDestroyed(TestListener.java:16)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:865)
	- locked <0x00000000f1d7c890> (a org.apache.catalina.session.StandardSession)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:823)
	at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:739)
	at org.apache.catalina.session.StandardManager.processExpires(StandardManager.java:1014)
	at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5731)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1835)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1824)
	at java.lang.Thread.run(Thread.java:662)

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

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

【IJServerクラスタ起動時のスレッド】

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

"pool-1-thread-7" prio=6 tid=0x0000000008fb1800 nid=0x1020 runnable [0x000000000a8af000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.init(TestServlet.java:39)
	at javax.servlet.GenericServlet.init(GenericServlet.java:270)
	at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1100)
	- locked <0x00000000fb3cd040> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1023)
	- locked <0x00000000fb3cd040> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4999)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:5406)
	- locked <0x00000000f0a9f4c8> (a com.sun.enterprise.web.WebModule)
	at com.sun.enterprise.web.WebModule.start(WebModule.java:345)
	- locked <0x00000000f0a9f4c8> (a com.sun.enterprise.web.WebModule)
	at com.sun.enterprise.web.LifecycleStarter.doRun(LifecycleStarter.java:58)
	at com.sun.appserv.management.util.misc.RunnableBase.runSync(RunnableBase.java:304)
	at com.sun.appserv.management.util.misc.RunnableBase.run(RunnableBase.java:341)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

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

【IJServerクラスタ停止時のスレッド】

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

"RMI TCP Connection(23)-127.0.0.1" daemon prio=6 tid=0x000000000988f800 nid=0x1030 runnable [0x000000000bb0d000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.destroy(TestServlet.java:43)
	at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1461)
	- locked <0x00000000f1dc8120> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardWrapper.stop(StandardWrapper.java:1824)
	at org.apache.catalina.core.StandardContext.stop(StandardContext.java:5531)
	- locked <0x00000000f1dc8418> (a com.sun.enterprise.web.WebModule)
   ・・・中略・・・
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

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

前次
Copyright 2002-2014 FUJITSU LIMITED