Hatena::ブログ(Diary)

yamadamnのはてな日記 Twitter

2014-12-07

スレッドダンプから見るWebLogic Serverの世界 #javaee

この記事はJava EE Advent Calendarの7日目です。
前回のブログ記事を振り返ると、もう一年前。Advent Calendarでしか書いてない訳です。
それであれば、さすがにネタがあるかなと思ったのですが、何も思い浮かばない…
いつものWebLogic Server(以降、基本的にWLSと略)ネタでお許しください。

Javaアプリケーションサーバーの特徴的なところは、スレッド管理にあると私は思っています。
そして、ここがチューニング観点としても非常に重要なところです。
そのため、各アプリケーションサーバーの実装によって、工夫を凝らしているところです。

この記事では、スレッドダンプからWLSの世界を垣間見てみましょう。

WLSスレッド管理概要

といっても、いきなりスレッドダンプを見ても迷子になるので、まずはWLSのスレッド管理概要を知っておきましょう。
既に多くの分かりやすい資料がありますので、以下辺りにある図を参照してください。

簡単に言うと、以下の構成になっています。

そして、アプリケーション処理には一つの実行スレッドプールを共有し、それを個々のワークマネージャを構成して制御するようになっています。

スレッドダンプを取得する

さて、スレッドダンプがどうなっているか見てみましょう。環境は以下の通りです。

スレッドダンプを取得するには様々な方法がありますが、最近*2ならjcmdを使うのが常套手段ですかね。
スレッドダンプは、その時点のスレッド状態のスナップショットなので刻々と変わりますが、以下はWLS起動が完了した(RUNNING状態になった)直後くらいのものです。
長くなるので、ざくっと雰囲気だけ見てもらって、読み飛ばしてください。

$ jcmd
10898 weblogic.Server
10899 sun.tools.jcmd.JCmd
$ jcmd 10898 Thread.print 
10898:
2014-12-06 16:59:00
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.25-b02 mixed mode):

"DynamicListenThread[Default]" #45 daemon prio=9 os_prio=31 tid=0x00007fb0883cb800 nid=0x7203 runnable [0x000000012b3ef000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)
	- locked <0x0000000781d33a28> (a java.lang.Object)
	at weblogic.socket.WeblogicServerSocket.accept(WeblogicServerSocket.java:31)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.accept(DynamicListenThread.java:532)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.access$200(DynamicListenThread.java:414)
	at weblogic.server.channels.DynamicListenThread.run(DynamicListenThread.java:173)
	at java.lang.Thread.run(Thread.java:745)

"DynamicListenThread[Default[1]]" #44 daemon prio=9 os_prio=31 tid=0x00007fb085237000 nid=0x7003 runnable [0x000000012b2ec000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)
	- locked <0x0000000781d7c6b8> (a java.lang.Object)
	at weblogic.socket.WeblogicServerSocket.accept(WeblogicServerSocket.java:31)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.accept(DynamicListenThread.java:532)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.access$200(DynamicListenThread.java:414)
	at weblogic.server.channels.DynamicListenThread.run(DynamicListenThread.java:173)
	at java.lang.Thread.run(Thread.java:745)

"DynamicListenThread[Default[2]]" #43 daemon prio=9 os_prio=31 tid=0x00007fb0850e9800 nid=0x3207 runnable [0x000000012af44000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)
	- locked <0x0000000781d7d6a8> (a java.lang.Object)
	at weblogic.socket.WeblogicServerSocket.accept(WeblogicServerSocket.java:31)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.accept(DynamicListenThread.java:532)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.access$200(DynamicListenThread.java:414)
	at weblogic.server.channels.DynamicListenThread.run(DynamicListenThread.java:173)
	at java.lang.Thread.run(Thread.java:745)

"weblogic.GCMonitor" #41 daemon prio=5 os_prio=31 tid=0x00007fb088330000 nid=0x3707 in Object.wait() [0x000000012623c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
	- locked <0x0000000781a351d0> (a java.lang.ref.ReferenceQueue$Lock)
	at weblogic.platform.GCMonitorThread.waitForNotification(GCMonitorThread.java:86)
	at weblogic.platform.GCMonitorThread.run(GCMonitorThread.java:62)

"Thread-18" #40 prio=5 os_prio=31 tid=0x00007fb085bc0000 nid=0x300b waiting on condition [0x0000000125312000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000007816d99f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at weblogic.utils.concurrent.JDK15ConcurrentBlockingQueue.take(JDK15ConcurrentBlockingQueue.java:89)
	at weblogic.store.internal.PersistentStoreImpl.getOutstandingWork(PersistentStoreImpl.java:724)
	at weblogic.store.internal.PersistentStoreImpl.synchronousFlush(PersistentStoreImpl.java:1124)
	at weblogic.store.internal.PersistentStoreImpl.run(PersistentStoreImpl.java:1116)
	at java.lang.Thread.run(Thread.java:745)

"[STANDBY] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" #39 daemon prio=5 os_prio=31 tid=0x00007fb084c58000 nid=0x6d03 in Object.wait() [0x0000000128ca7000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x0000000780cf2d08> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" #38 daemon prio=5 os_prio=31 tid=0x00007fb084a81800 nid=0x6b03 runnable [0x0000000128ba4000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
	- locked <0x0000000780a12978> (a sun.nio.ch.Util$2)
	- locked <0x0000000780a12968> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000780a12838> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
	at weblogic.socket.NIOSocketMuxer.selectFrom(NIOSocketMuxer.java:529)
	at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:458)
	at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
	at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" #37 daemon prio=5 os_prio=31 tid=0x00007fb0845d4000 nid=0x6903 runnable [0x0000000128aa1000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
	- locked <0x0000000780a13310> (a sun.nio.ch.Util$2)
	- locked <0x0000000780a13300> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000780a131e0> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
	at weblogic.socket.NIOSocketMuxer.selectFrom(NIOSocketMuxer.java:529)
	at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:458)
	at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
	at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" #36 daemon prio=5 os_prio=31 tid=0x00007fb08557e800 nid=0x6703 runnable [0x000000012899e000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
	- locked <0x0000000780a13ca8> (a sun.nio.ch.Util$2)
	- locked <0x0000000780a13c98> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000780a13b78> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
	at weblogic.socket.NIOSocketMuxer.selectFrom(NIOSocketMuxer.java:529)
	at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:458)
	at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
	at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" #35 daemon prio=5 os_prio=31 tid=0x00007fb0845b6000 nid=0x6503 runnable [0x000000012736f000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
	- locked <0x0000000780a14640> (a sun.nio.ch.Util$2)
	- locked <0x0000000780a14630> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000780a14510> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
	at weblogic.socket.NIOSocketMuxer.selectFrom(NIOSocketMuxer.java:529)
	at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:458)
	at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
	at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

"Thread-17" #34 prio=5 os_prio=31 tid=0x00007fb0840eb800 nid=0x6107 waiting on condition [0x000000012726c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000780c018b0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at weblogic.utils.concurrent.JDK15ConcurrentBlockingQueue.take(JDK15ConcurrentBlockingQueue.java:89)
	at weblogic.store.internal.PersistentStoreImpl.getOutstandingWork(PersistentStoreImpl.java:724)
	at weblogic.store.internal.PersistentStoreImpl.synchronousFlush(PersistentStoreImpl.java:1124)
	at weblogic.store.internal.PersistentStoreImpl.run(PersistentStoreImpl.java:1116)
	at java.lang.Thread.run(Thread.java:745)

"DoSManager" #33 daemon prio=6 os_prio=31 tid=0x00007fb0841e0800 nid=0x6303 waiting on condition [0x000000012749b000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.octetstring.vde.DoSManager.run(DoSManager.java:433)

"VDE Transaction Processor Thread" #31 daemon prio=2 os_prio=31 tid=0x00007fb084b85800 nid=0x4d07 in Object.wait() [0x0000000127169000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at com.octetstring.vde.backend.standard.TransactionProcessor.waitChange(TransactionProcessor.java:367)
	- locked <0x000000078097c808> (a com.octetstring.vde.backend.standard.TransactionProcessor)
	at com.octetstring.vde.backend.standard.TransactionProcessor.run(TransactionProcessor.java:212)

"[STANDBY] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" #26 daemon prio=5 os_prio=31 tid=0x00007fb08530a000 nid=0x5107 in Object.wait() [0x00000001257f7000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x0000000780cf3ee0> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"[STANDBY] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" #25 daemon prio=5 os_prio=31 tid=0x00007fb085226000 nid=0x5307 in Object.wait() [0x00000001256f4000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x0000000780d0e7f0> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" #24 daemon prio=5 os_prio=31 tid=0x00007fb0848b8000 nid=0x4f0f in Object.wait() [0x00000001255f1000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x0000000780d22830> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"weblogic.timers.TimerThread" #22 daemon prio=9 os_prio=31 tid=0x00007fb084512800 nid=0x5f03 in Object.wait() [0x0000000126e66000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at weblogic.timers.internal.TimerThread.doWait(TimerThread.java:114)
	- locked <0x00000007805f69e8> (a java.lang.Object)
	at weblogic.timers.internal.TimerThread.access$000(TimerThread.java:22)
	at weblogic.timers.internal.TimerThread$Thread.run(TimerThread.java:290)

"weblogic.time.TimeEventGenerator" #21 daemon prio=9 os_prio=31 tid=0x00007fb086097800 nid=0x5d03 in Object.wait() [0x0000000126d63000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at weblogic.time.common.internal.TimeTable.snooze(TimeTable.java:286)
	- locked <0x0000000780675500> (a weblogic.time.common.internal.TimeTable)
	at weblogic.time.common.internal.TimeEventGenerator.run(TimeEventGenerator.java:117)
	at java.lang.Thread.run(Thread.java:745)

"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" #20 daemon prio=5 os_prio=31 tid=0x00007fb0845a6800 nid=0x5b03 in Object.wait() [0x00000001265c9000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x000000078064c548> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"Timer-2" #19 daemon prio=5 os_prio=31 tid=0x00007fb08618e800 nid=0x5903 in Object.wait() [0x0000000125125000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.util.TimerThread.mainLoop(Timer.java:552)
	- locked <0x00000007805f6cc0> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

"Attach Listener" #18 daemon prio=9 os_prio=31 tid=0x00007fb085c42800 nid=0x5703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Timer-1" #17 daemon prio=5 os_prio=31 tid=0x00007fb08449a800 nid=0x5503 in Object.wait() [0x00000001259fd000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007805f7258> (a java.util.TaskQueue)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	- locked <0x00000007805f7258> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

"Timer-0" #11 daemon prio=5 os_prio=31 tid=0x00007fb085bc4800 nid=0x4b03 in Object.wait() [0x00000001254ee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000078064bdf8> (a java.util.TaskQueue)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	- locked <0x000000078064bdf8> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

"Service Thread" #8 daemon prio=9 os_prio=31 tid=0x00007fb085056000 nid=0x4703 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fb084038800 nid=0x4503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fb084038000 nid=0x4303 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fb084032000 nid=0x4103 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fb084006000 nid=0x3417 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fb08581a800 nid=0x2d03 in Object.wait() [0x0000000121c71000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
	- locked <0x0000000780204778> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fb08581a000 nid=0x2b03 in Object.wait() [0x0000000121b6e000]
   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)
	- locked <0x00000007800489b0> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=31 tid=0x00007fb085005000 nid=0xd03 in Object.wait() [0x000000010d8db000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.t3.srvr.T3Srvr.waitForDeath(T3Srvr.java:1130)
	- locked <0x00000007803aef20> (a weblogic.t3.srvr.T3Srvr)
	at weblogic.t3.srvr.T3Srvr.run(T3Srvr.java:538)
	at weblogic.Server.main(Server.java:65)

"VM Thread" os_prio=31 tid=0x00007fb085815800 nid=0x2903 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fb08400a800 nid=0x2103 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fb08400b000 nid=0x2303 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fb08400c000 nid=0x2503 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fb08400c800 nid=0x2703 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007fb08501b000 nid=0x4903 waiting on condition 

JNI global references: 46

では見て行きましょう。
すべてではなく、JVMで利用するスレッド(コンパイラスレッドGCスレッドなど)は解説しませんので、ご了承ください。
また、推測を多々含むため、誤っている箇所もあるかもしれませんが、何卒ご容赦くださいませ。

まずは先ほど解説したリクエスト処理の要となるスレッド群からです。

Listenスレッド

「DynamicListenThread」から始まるスレッドが該当します。例えば以下です。

"DynamicListenThread[Default]" #45 daemon prio=9 os_prio=31 tid=0x00007fb0883cb800 nid=0x7203 runnable [0x000000012b3ef000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)
	- locked <0x0000000781d33a28> (a java.lang.Object)
	at weblogic.socket.WeblogicServerSocket.accept(WeblogicServerSocket.java:31)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.accept(DynamicListenThread.java:532)
	at weblogic.server.channels.DynamicListenThread$SocketAccepter.access$200(DynamicListenThread.java:414)
	at weblogic.server.channels.DynamicListenThread.run(DynamicListenThread.java:173)
	at java.lang.Thread.run(Thread.java:745)

サーバーソケットで接続要求をひたすら待機している様子が確認できますね。
このListenスレッドは、リスニングするチャネルごとに作成されます。
チャネルとはリスニングするアドレス・ポート(正確にはプロトコル含む)の組み合わせだと思ってください。
起動時のログで以下のように出力されます。

<Notice> <Server> <BEA-002613> <Channel "Default" is now listening on 192.168.0.2:7001 for protocols iiop, t3, ldap, snmp, http.> 
<Notice> <Server> <BEA-002613> <Channel "Default[2]" is now listening on 127.0.0.1:7001 for protocols iiop, t3, ldap, snmp, http.> 
<Notice> <Server> <BEA-002613> <Channel "Default[1]" is now listening on 0:0:0:0:0:0:0:1:7001 for protocols iiop, t3, ldap, snmp, http.> 

上記に出ているDefaultチャネルは少し特殊で、サーバインスタンス単位のリスニングアドレスとポートに基づいて作成され、複数のプロトコルをサポートしています。
Default[1]やDefault[2]のように数字がついているのは、リスニングアドレスが空の場合、OSにバインドされているすべてのIPアドレスに紐付いて構成されるためです。
しかし、プロダクション環境では、リスニングアドレスを空にすることは避け、明示的に単一のアドレスを指定すべきです。それ以外のアドレスでリスニングしたい場合は、カスタムのチャネルを構成することもでき、その際は明示的にhttp(s)などのプロトコルを指定します。
以前、WebLogic Server勉強会でも話したので、よろしければ参照ください。

管理コンソールからチャネルごとの統計情報を取得することもできます。

f:id:yamadamn:20141207005849p:image

チャネルについての詳細は、以下のマニュアルから確認できます。

Muxer(マルチプレクサ)スレッド

「ExecuteThread: 'n' for queue: 'weblogic.socket.Muxer'」が該当します。例えば以下です。

"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" #35 daemon prio=5 os_prio=31 tid=0x00007fb0845b6000 nid=0x6503 runnable [0x000000012736f000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
	- locked <0x0000000780a14640> (a sun.nio.ch.Util$2)
	- locked <0x0000000780a14630> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000780a14510> (a sun.nio.ch.KQueueSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
	at weblogic.socket.NIOSocketMuxer.selectFrom(NIOSocketMuxer.java:529)
	at weblogic.socket.NIOSocketMuxer.processSockets(NIOSocketMuxer.java:458)
	at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:30)
	at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:43)
	at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:147)
	at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:119)

ここではNIOSocketMuxerというMuxer実装が使われていることが分かります。
OSごとにNative Muxer実装も存在します。例えば、WindowsだとNTSocketMuxer、Unix環境だとPosixSocketMuxerやDevPollSocketMuxerがあり、以前はデフォルトで利用されていました。*3
Native実装はパフォーマンスはよいのですが、稀にクラッシュしたり、解析しづらいNativeメモリリークを引き起こすことがあります。
このため、切り分けとしてJava Socket Muxerを使ったり、別のMuxer実装を利用するように変更することもできます。

f:id:yamadamn:20141207005850p:image
:
f:id:yamadamn:20141207005851p:image

Muxerについては、以下のマニュアルから確認できます。

実行スレッド

「[STATE] ExecuteThread: 'n' for queue: 'weblogic.kernel.Default (self-tuning)'」が該当します。例えば以下です。

"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" #20 daemon prio=5 os_prio=31 tid=0x00007fb0845a6800 nid=0x5b03 in Object.wait() [0x00000001265c9000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x000000078064c548> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

"[STANDBY] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" #39 daemon prio=5 os_prio=31 tid=0x00007fb084c58000 nid=0x6d03 in Object.wait() [0x0000000128ca7000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:247)
	- locked <0x0000000780cf2d08> (a weblogic.work.ExecuteThread)
	at weblogic.work.ExecuteThread.run(ExecuteThread.java:281)

この実行スレッドが一番の肝です。例えばハングアップやスローダウンが発生する場合は、アプリケーション処理が問題になっていることが多いため、スレッドダンプを解析する際には、この辺りを中心に見ていくことになります。
今回は解析方法には触れませんが、ThreadLogicといったツールが役に立ちます。

スレッド名を構成する要素を細かく見て行きましょう。

[STATE]

実行スレッドの管理状態が付加されており、以下の3種類があります。


STATE説明
ACTIVEスレッドがリクエストを実行中であるか、またはリクエストをすぐに実行できる状態
STANDBYアクティブなスレッドプールから削除されていて、リクエストをすぐには処理できない状態
STUCKリクエストを実行中だが、しばらく経っても完了していない状態

ACTIVEだからといって必ずしもリクエストを実行中な訳ではないことに注意してください。*4
STANDBYでもなくアイドル状態にもなっていない場合は、リクエストを実行しているとみなすことができ、この詳細はJMX(管理コンソールなど)で確認できます。

f:id:yamadamn:20141207021121p:image
:
f:id:yamadamn:20141207024549p:image

STUCKは少し特殊な状態です。WLSは定期的に実行スレッドを監視しており、デフォルトで600秒(10分)以上リクエストを実行中のスレッドをこの状態にマークします。“スタック”とカタカナで書いたり発音すると、スレッドの話から"Stack"と勘違いしやすいのですが、詰まったとかを意味する"Stuck"ですね。
ハングアップが長期間続いている場合は、ここから見ていくといいでしょう。ログにも以下のように出力されます。

<Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "601" seconds working on the request "Workmanager: default, Version: 0, Scheduled=false, Started=true, Started time: 601951 ms
", which is more than the configured time (StuckThreadMaxTime) of "600" seconds in "server-failure-trigger". Stack trace:
	java.lang.Thread.sleep(Native Method)
	com.munzandmore.stuckthread.LongRunningEJB.threadSleep(LongRunningEJB.java:26)
	com.munzandmore.stuckthread.LongRunningEJB_x9v26k_NoIntfViewImpl.__WL_invoke(Unknown Source)
	weblogic.ejb.container.internal.SessionLocalMethodInvoker.invoke(SessionLocalMethodInvoker.java:33)
	weblogic.ejb.container.internal.AsyncExecutor$Invoker.invoke(AsyncExecutor.java:205)
	weblogic.ejb.container.internal.AsyncExecutor.run(AsyncExecutor.java:73)
	weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:548)
	weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
	weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
> 

ExecuteThread: 'n' for queue:

ここはさらっと流しましょう。実行スレッドごとに順番がつけられています。
先ほど説明したMuxerも実行スレッドの機能を流用しているのか、同じような名前になっていますね。

'weblogic.kernel.Default (self-tuning)'

スレッドの自動チューニングがされていることを意味します。
この文言は基本的に固定なのですが、もう少し分かりやすくする方法があります。12/18のWebLogic Server勉強会で説明する予定ですので、よろしければ参加ください。

さて、自動チューニングについてです。

WLSの実行スレッドは初期では少なめで、リクエスト流量によって増えるようになっています。これによってスレッドリソースの無駄もなくしつつ、管理者の設計や設定作業の負荷も最小限に抑えることができます。

勘違いしやすいところとして、ワークマネージャの設定では最大スレッド数制約などを指定できますが、物理的なスレッドを直接的に増やす訳ではありません。どちらかというとワークマネージャは論理的にスレッド数を制御する機構と考えてください。
多くの場合、自動チューニングに任せておいて問題ないのですが、起動直後にバーストトラフィックが予想されるようなシステムでは、物理的なスレッド数を予め確保しておきたい場合もあります。
以前は、WLST(WebLogic Scripting Tool)や起動オプションによる設定のみで隠しパラメータ的な扱いだったのですが、WLS 12.1.2以降では管理コンソールから指定できるようになっています。

f:id:yamadamn:20141207005850p:image
:
f:id:yamadamn:20141207024550p:image
最大プールサイズも構成できますが、余程のことがない限り、デフォルトの400より増やさない方が無難です。多すぎるスレッドの確保はリソースの枯渇を招きやすいですし、OSコンテキストスイッチオーバーヘッド増加も気になります。*5

余談ですが、WLS 8.1までは自動チューニングはなく、個々の実行キューに対し、スレッドプールを持っていました。これは詳しい方なら分かりやすい方法ではあったのですが、下手すると過剰な設定になりがちでした。現在は自動チューニングを踏まえて、ワークマネージャで制御する方が一般的かと思います。*6

自動チューニングについては、以下のマニュアルなどから確認できます。

かなり長くなりましたね。ここまでで主要な部分の説明は終わりです。
後は落穂拾い的な感じですが、よろしければお付き合いください。

mainスレッド

"main" #1 prio=5 os_prio=31 tid=0x00007fb085005000 nid=0xd03 in Object.wait() [0x000000010d8db000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at weblogic.t3.srvr.T3Srvr.waitForDeath(T3Srvr.java:1130)
	- locked <0x00000007803aef20> (a weblogic.t3.srvr.T3Srvr)
	at weblogic.t3.srvr.T3Srvr.run(T3Srvr.java:538)
	at weblogic.Server.main(Server.java:65)

これを見るとエントリポイントが、weblogic.Serverクラスのmainメソッドになっていることが分かりますね。*7
起動スクリプト({WLSドメイン}/bin配下のstartWebLogic.shやsetDomainEnv.sh)でも、この様子は確認できます。

# startWebLogic.sh抜粋
if [ "${WLS_REDIRECT_LOG}" = "" ] ; then
        echo "Starting WLS with line:"
        echo "${JAVA_HOME}/bin/java ${JAVA_VM} ${MEM_ARGS} -Dweblogic.Name=${SERVER_NAME} -Djava.security.policy=${WL_HOME}/server/lib/weblogic.policy ${JAVA_OPTIONS} ${PROXY_SETTINGS} ${SERVER_CLASS}"
        ${JAVA_HOME}/bin/java ${JAVA_VM} ${MEM_ARGS} -Dweblogic.Name=${SERVER_NAME} -Djava.security.policy=${WL_HOME}/server/lib/weblogic.policy ${JAVA_OPTIONS} ${PROXY_SETTINGS} ${SERVER_CLASS}
else
        echo "Redirecting output from WLS window to ${WLS_REDIRECT_LOG}"
        ${JAVA_HOME}/bin/java ${JAVA_VM} ${MEM_ARGS} -Dweblogic.Name=${SERVER_NAME} -Djava.security.policy=${WL_HOME}/server/lib/weblogic.policy ${JAVA_OPTIONS} ${PROXY_SETTINGS} ${SERVER_CLASS}  >"${WLS_REDIRECT_LOG}" 2>&1
fi
# setDomainEnv.sh抜粋
SERVER_CLASS="weblogic.Server"
export SERVER_CLASS

起動スクリプトの詳細は、WebLogic Server勉強会で話した内容を記事にしていただいているので参照ください。*8

スタックトレースに見られるt3というのは、チャネルのところで少しだけ出てきましたが、WLSの独自プロトコルです。
それほど意識することはありませんが、以下のマニュアルで確認できます。

GCMonitorスレッド

"weblogic.GCMonitor" #41 daemon prio=5 os_prio=31 tid=0x00007fb088330000 nid=0x3707 in Object.wait() [0x000000012623c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
	- locked <0x0000000781a351d0> (a java.lang.ref.ReferenceQueue$Lock)
	at weblogic.platform.GCMonitorThread.waitForNotification(GCMonitorThread.java:86)
	at weblogic.platform.GCMonitorThread.run(GCMonitorThread.java:62)

WLSには周期的にヒープの空き状況を監視し、ログ出力する機能があるため、ここで用いられていると想定されます。
RefereceQueueの仕組みを利用しているので、GCイベントと関連づけていることが分かりますね。
WLSサーバログ({WLSドメイン}/servers/{サーバ名}/logs/{サーバ名.log})への出力例は以下のようになります。

####<2014/12/06 23時30分13秒 JST> <Info> <Health> <mymachine> <myserver> <weblogic.GCMonitor> <<anonymous>> <> <> <1417876213715> <BEA-310002> <サーバーの総メモリーの70%が空いています。> 
####<2014/12/06 23時33分13秒 JST> <Info> <Health> <mymachine> <myserver> <weblogic.GCMonitor> <<anonymous>> <> <> <1417876393683> <BEA-310002> <サーバーの総メモリーの33%が空いています。> 

Timer関連スレッド

"weblogic.timers.TimerThread" #22 daemon prio=9 os_prio=31 tid=0x00007fb084512800 nid=0x5f03 in Object.wait() [0x0000000126e66000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at weblogic.timers.internal.TimerThread.doWait(TimerThread.java:114)
	- locked <0x00000007805f69e8> (a java.lang.Object)
	at weblogic.timers.internal.TimerThread.access$000(TimerThread.java:22)
	at weblogic.timers.internal.TimerThread$Thread.run(TimerThread.java:290)

"weblogic.time.TimeEventGenerator" #21 daemon prio=9 os_prio=31 tid=0x00007fb086097800 nid=0x5d03 in Object.wait() [0x0000000126d63000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at weblogic.time.common.internal.TimeTable.snooze(TimeTable.java:286)
	- locked <0x0000000780675500> (a weblogic.time.common.internal.TimeTable)
	at weblogic.time.common.internal.TimeEventGenerator.run(TimeEventGenerator.java:117)
	at java.lang.Thread.run(Thread.java:745)
"Timer-0" #11 daemon prio=5 os_prio=31 tid=0x00007fb085bc4800 nid=0x4b03 in Object.wait() [0x00000001254ee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x000000078064bdf8> (a java.util.TaskQueue)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	- locked <0x000000078064bdf8> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

一般的なjava.util.Timerも使われていますが、WLSの様々なタスクを実現するために、拡張されたタイマーサービスが用意されています。
タイマーの状況は管理コンソールから確認できます。これを見ると更に新たな発見があるかもしれません。

f:id:yamadamn:20141207113240p:image

WLS独自のタイマーサービスのマニュアルは、以下を参照してください。

組込みLDAP関連スレッド

"DoSManager" #33 daemon prio=6 os_prio=31 tid=0x00007fb0841e0800 nid=0x6303 waiting on condition [0x000000012749b000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep(Native Method)
	at com.octetstring.vde.DoSManager.run(DoSManager.java:433)

"VDE Transaction Processor Thread" #31 daemon prio=2 os_prio=31 tid=0x00007fb084b85800 nid=0x4d07 in Object.wait() [0x0000000127169000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at com.octetstring.vde.backend.standard.TransactionProcessor.waitChange(TransactionProcessor.java:367)
	- locked <0x000000078097c808> (a com.octetstring.vde.backend.standard.TransactionProcessor)
	at com.octetstring.vde.backend.standard.TransactionProcessor.run(TransactionProcessor.java:212)

WLSにはユーザー・グループなどを管理するために組込みLDAPが用意されています。
管理サーバーをマスタとしますが、ドメイン内に他のサーバー(管理対象サーバー)がある場合は、それぞれに組込みLDAPリポジトリがありレプリケーションされます。これらの管理に用いられていると推測されます。

組込みLDAPマニュアルは、以下を参照してください。

なお、スタックトレース中のvdeは、Virtual Directory Engineを意味するようです。

永続ストア関連スレッド

"Thread-17" #34 prio=5 os_prio=31 tid=0x00007fb0840eb800 nid=0x6107 waiting on condition [0x000000012726c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000780c018b0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at weblogic.utils.concurrent.JDK15ConcurrentBlockingQueue.take(JDK15ConcurrentBlockingQueue.java:89)
	at weblogic.store.internal.PersistentStoreImpl.getOutstandingWork(PersistentStoreImpl.java:724)
	at weblogic.store.internal.PersistentStoreImpl.synchronousFlush(PersistentStoreImpl.java:1124)
	at weblogic.store.internal.PersistentStoreImpl.run(PersistentStoreImpl.java:1116)
	at java.lang.Thread.run(Thread.java:745)

スレッド名がちゃんと付いていない*9のですが、スタックトレースから永続ストアの書込みに利用されると想定されます。
明示的にカスタムのストアを構成しない場合でも、デフォルトの永続ストアがあり、JTAのトランザクションログなどの管理に用いられます。

永続ストアのマニュアルは、以下を参照してください。

他にも説明できていない箇所が多々あるとは思いますが、ひとまずこれで終了です。大変お疲れさまでした!*10

まとめ

  • スレッドダンプからWLSのアーキテクチャの一端を垣間見ることができます。
  • リクエスト処理の要となるListen/Muxer/実行スレッドは知っておくとよいです。
  • 他の製品でもスレッドダンプとか調べると面白いかもしれません。

明日は @ さんです。

*1:WLS 12.1.3はOracle JDK 8u20以降で動作保証していますが、Fork/Join Frameworkやパラレルストリームはサポートしていません。また、Mac OS X 10.10は記事執筆時点では正式動作保証はされていません。

*2:正確には7u4以降

*3:正確にはWLS 12.1.2以降でNIOSocketMuxerがデフォルトになりました。

*4:もちろん個々のスタックトレースの内容から判別はつくのですが、監視などの観点からはいちいち見ていられません。

*5スレッドが多すぎるスレッドダンプを解析するのも非常につらいです。お願いだから勘弁してください…

*6:WLS 8.1までのスレッドモデルを利用するように構成することもできますが、あまり使ってほしくないので説明を割愛します。

*7スレッドダンプを取得した時点でもweblogic.Serverであることは分かっていますが。

*8:今では少し古くなっているので12/18の勉強会で補足する予定です。

*9:WLSに限りませんが、スレッド名は適切に付けないと分かりづらいので、きちんと付けてほしいですね。

*10:最後まで読んでくれた稀有な方がいればですが…

スパム対策のためのダミーです。もし見えても何も入力しないでください
ゲスト


画像認証