ページの先頭行へ戻る
Interstage Application Server/Interstage Web Server Express Java EE運用ガイド(Java EE 6編)
FUJITSU Software
第11章 トラブルシューティング > 11.10 スレッドダンプが出力された場合の対処
前次

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

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

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

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

「2.5.5 生存通知の監視」

■出力例

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

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

"http-thread-pool-24858(16)" daemon prio=6 tid=0x000000000a87f000 nid=0x19c0 in Object.wait() [0x0000000010a4f000]
   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.grizzly.util.SyncThreadPool$SyncThreadWorker.getTask(SyncThreadPool.java:381)
	- locked <0x00000000f7396fe8> (a java.lang.Object)
	at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:531)
	at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:520)
	at java.lang.Thread.run(Thread.java:722)

 ・・・中略・・・

"Finalizer" daemon prio=8 tid=0x000000000650c000 nid=0x1948 in Object.wait() [0x0000000006e6f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000e00a4e80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
	- locked <0x00000000e00a4e80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x00000000018f6000 nid=0x1a84 in Object.wait() [0x0000000006a3e000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000e00a4bd0> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x00000000e00a4bd0> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x00000000018e8000 nid=0x1b08 runnable 

"GC task thread#0 (ParallelGC)" prio=6 tid=0x0000000001835800 nid=0x193c runnable 

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

"VM Periodic Task Thread" prio=10 tid=0x000000000663c800 nid=0x1524 waiting on condition 

"RAS Control Thread" prio=10 tid=0x00000000018e6800 nid=0x14c8 runnable

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

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

出力例
"http-thread-pool-28292(4)" daemon prio=6 tid=0x000000000a47b800 nid=0xa18 waiting on condition [0x000000000d6fe000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at samples.TestServlet.doGet(TestServlet.java:12)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
   ・・・以下省略・・・

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

解析方法

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

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

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

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

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


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

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

"http-thread-pool-28292(4)" daemon prio=6 tid=0x000000000a47b800 nid=0xa18 runnable [0xc837e000]
   java.lang.Thread.State: RUNNABLE
	at samples.TestServlet.doGet(TestServlet.java:15)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
	at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1550)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:343)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:217)
   ・・・以下省略・・・

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


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

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

"http-thread-pool-28292(2)" daemon prio=6 tid=0x000000000a9a1800 nid=0x1ac8 waiting on condition [0x0000000010e4e000]
   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:117)
	at org.apache.jsp.test_jsp._jspService(test_jsp.java:89)
	at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:111)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
	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:770)
   ・・・以下省略・・・

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


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

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

"http-thread-pool-28292(4)" daemon prio=6 tid=0x000000000919f800 nid=0x1888 waiting on condition [0x000000001193e000]
   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:217)
	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:217)
   ・・・以下省略・・・

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

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

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

"ContainerBackgroundProcessor[StandardEngine[glassfish-web].StandardHost[server].StandardContext[/examples]]" daemon prio=6 tid=0x000000000b15d800 nid=0x1710 runnable [0x000000001220f000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestListener.sessionDestroyed(TestListener.java:16)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:807)
	- locked <0x00000000f87d8198> (a org.apache.catalina.session.StandardSession)
	at org.apache.catalina.session.StandardSession.expire(StandardSession.java:769)
	at org.apache.catalina.session.StandardSession.isValid(StandardSession.java:686)
	at org.apache.catalina.session.StandardManager.processExpires(StandardManager.java:997)
	at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5779)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1793)
	at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1782)
	at java.lang.Thread.run(Thread.java:722)

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

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

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

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

 "main" prio=6 tid=0x0000000001825000 nid=0xc40 runnable [0x0000000001b8d000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.init(TestServlet.java:44)
	at javax.servlet.GenericServlet.init(GenericServlet.java:244)
	at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1453)
	at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1250)
	- locked <0x00000000f728af00> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5093)
	at org.apache.catalina.core.StandardContext.start(StandardContext.java:5380)
	- locked <0x00000000f7237a00> (a com.sun.enterprise.web.WebModule)
	   ・・・中略・・・
	at com.sun.enterprise.glassfish.bootstrap.GlassFishMain.main(GlassFishMain.java:97)
	at com.sun.enterprise.glassfish.bootstrap.ASMain.main(ASMain.java:55)

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

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

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

 "Thread-34" daemon prio=6 tid=0x000000000a879000 nid=0x18bc runnable [0x00000000108ce000]
   java.lang.Thread.State: RUNNABLE
	at examples.TestServlet.destroy(TestServlet.java:55)
	at org.apache.catalina.core.StandardWrapper.unload(StandardWrapper.java:1769)
	- locked <0x00000000fa8d46f8> (a org.apache.catalina.core.StandardWrapper)
	at org.apache.catalina.core.StandardWrapper.stop(StandardWrapper.java:2070)
	at org.apache.catalina.core.StandardContext.stop(StandardContext.java:5559)
	- locked <0x00000000fa8d43d0> (a com.sun.enterprise.web.WebModule)
	・・・中略・・・
	at com.sun.enterprise.v3.admin.CommandRunnerImpl$1.execute(CommandRunnerImpl.java:348)
	at com.sun.enterprise.v3.admin.CommandRunnerImpl$2.run(CommandRunnerImpl.java:377)

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

前次
Copyright 2011-2014 FUJITSU LIMITED