yamadamn’s blog

IT関連技術で経験したこと・気になったことをたまに書きます

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

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

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

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

WLSスレッド管理概要

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

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

  • リクエストを受け付けてソケットリーダーに渡すListenスレッド
  • ソケットを読み込んで実行スレッドに受け渡すMuxer(マルチプレクサ)スレッド
  • 実際のアプリケーション処理などを実行する実行スレッド

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

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

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

スレッドダンプを取得するには様々な方法がありますが、最近*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勉強会でも話したので、よろしければ参照ください。

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

  • 環境→サーバー→{サーバー名}→監視→チャネル

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

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実装を利用するように変更することもできます。

  • 環境→サーバー→{サーバー名}→構成→チューニング


:

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(管理コンソールなど)で確認できます。

  • 環境→サーバー→{サーバー名}→監視→スレッド


:

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以降では管理コンソールから指定できるようになっています。

  • 環境→サーバー→{サーバー名}→構成→チューニング→詳細→自動チューニングスレッド最小プールサイズ


:

最大プールサイズも構成できますが、余程のことがない限り、デフォルトの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の様々なタスクを実現するために、拡張されたタイマーサービスが用意されています。
タイマーの状況は管理コンソールから確認できます。これを見ると更に新たな発見があるかもしれません。

  • 環境→サーバー→{サーバー名}→監視→タイマー

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/実行スレッドは知っておくとよいです。
  • 他の製品でもスレッドダンプとか調べると面白いかもしれません。

明日は [twitter:@btnrouge] さんです。

*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:最後まで読んでくれた稀有な方がいればですが…

JavaアプリケーションサーバでThreadLocal利用時の注意点

本日はJava EE Advent CalendarJPOUG Advent Calndarの14日目です*1

さて、先日11/9のJJUG CCCで話してきた内容で、Javaアプリケーションサーバでは、アプリケーションからThreadLocalは極力利用しない方がよいとのスライドを載せていました。
しかし、当日は時間がなく、また参考情報程度でしたので、説明を省いていました。
これについて、このエントリでは少し丁寧に説明をしたいと思います。

実は、上記スライドは、当日話した内容から以下の修正を加えています。

  • 「極力利用しない」→「注意して利用」に変更
  • 「再利用前提のスレッドに紐づくため、アプリで明示的に破棄」を追記

これがサマリにはなるのですが、説明していきましょう。

ThreadLocal

まず、ThreadLocalについて馴染みが薄い方もいると思いますので、簡単に復習しましょう。
ThreadLocalは、Javaでスレッドごとにオブジェクトを保持するための機構であり、スレッドセーフにデータの利用を行える便利なクラスです。
イメージ的には、カレントスレッドをキーに値の出し入れを行えるMapのようなものです*2

などが参考になります。
アプリケーションで直接的に利用しないでも、フレームワークや、3rd Party製のライブラリなどで使われているケースもあります。
例えば有名なロギングライブラリであるLog4jLogbackではMDC(Mapped Diagnostic Context)を実装するために、ThreadLocalが利用されています。

再利用前提のスレッド

Javaアプリケーションサーバでは、複数ユーザーからの同時アクセスを効率的に捌くために、リクエストごとにスレッドの生成や破棄を行うのではなく、スレッドプールを作成しておき、再利用するのが一般的です。

実装にもよりますが、アプリケーションサーバはそれぞれ一つのJavaプロセスとなり、一つ以上のアプリケーション(warやear)がデプロイされて動作することが多いです。
そのため、スレッドプールも複数のアプリケーションで共用されるリソースとなり、アプリケーションをアンデプロイしても、スレッドプールはそのまま残る実装が多いと思います。

もちろん、実際の運用では、アプリケーション間の競合を避けたり、独立性を保つために、アプリケーションごとにリソースを用意するケースもあるとは思いますが、基本的にはアプリケーションと、アプリケーションサーバのリソースは、できるだけ疎に保っておくような配慮が必要とされます。
これはスレッドプールだけではなく、DBとの接続プールなども同様です。

上記の組み合わせ

さて、「ThreadLocal」と「再利用前提のスレッド」を組み合わせたときにどうなるか。
何も考えていないと、アプリケーションサーバからアプリケーションをアンデプロイされても、スレッドは残ったままであり、ThreadLocalへの参照は破棄されません。
そのため、参照されているオブジェクトやクラスがGC対象とならず、残ってしまうことになりますので、メモリリークを発生させる要因となります。
以下の資料P22-P42で分かりやすく説明されていますので、図などを含めて参照してみてください。

ここでは、WebLogic Serverの本番再デプロイメントを繰り返し行うことにより、発生したOutOfMemoryErrorをJRockit Mission Controlに含まれるMemory Leak Detector*3を利用して特定・解決した例ですが、それに限らず、他製品での通常のアンデプロイや他のJVMでも発生するものです。

解決策

ThreadLocalを使わなければ原理的に発生はしないのですが、利用したい場合も多々発生しますし、3rd Partyのライブラリで暗黙的に利用されているケースもあります。
いくつか方法を提示しますが、実際には、デプロイ→アプリケーションの実行→アンデプロイを繰り返しテストして、メモリリークが発生しないよう確認ください。

リクエストごとに確実にThreadLocal#removeする

アプリケーションから直接ThreadLocalをハンドリングしている場合は、これを行うべきです。
リクエスト単位に値を初期化する使い方をする場合は、finallyやtry-with-resourcesでラッパーして、その中でThreadLocalの値を破棄するようにしましょう。
そうしなければ、再デプロイに限らず、他のリクエストで利用した値が見えてしまい、問題が発生することもあります。

3rd Partyライブラリなどで用意されている破棄メソッドを呼び出す
  • Log4Jであれば、LogManager.shutdownを呼び出す
  • LogBackであれば、LoggerContext#stopを呼び出す

などの方法があるようですが、正確にはそれぞれのライブラリのドキュメントなどを参照ください。
ServletContext#destroyの中などで行うとよいでしょう。

リフレクションを用いて削除する

ServletContext#destroyの中などで、リフレクションを用いてThreadLocalを破棄する方法も挙げられます。

のような実装が参考になるのではないでしょうか。
Tomcatの場合は自動削除に対応しているようです*4

アプリケーションのデプロイを行う際は、アプリケーションサーバの再起動も併せて実施する

身も蓋もないかもしれませんが、これを行うに越したことはありません。
ThreadLocalに限らず、それ以外のメモリリークを解消したり、起動時のみに発生する問題を検出するのにも有効です。
また、パッチを適用したり、構成を変更するときには、どうしても再起動が必須になるケースもあります。

まとめ

  • ThreadLocalを安易に利用することはメモリリークの原因になり得ます。
  • WebLogic Serverの本番再デプロイメント機能などを利用して無停止運用を実現する場合、繰り返しテストしてメモリリークが発生しないか確認してください。
  • デプロイ時に再起動を行うのは有効です。これが可能なように構成や運用も考慮してください。

*1:今年はどちらも被せてしまったがお許しを…

*2:実際の実装としては正確ではなく、あくまでイメージです

*3:HotSpot 7u40と併せてリリースされたJava Mission Control 5.2では残念ながらまだ移植されていません

*4:WebLogic Serverとかも同様の機能があるとよいなぁと思ったり

#jjug_ccc で「Javaアプリケーションサーバ 構築・運用の勘所」について話してきた

11/9(土)にベルサール西新宿で行われたJJUG CCC 2013 Fallに登壇してきました。

Call for Papersには通ったものの、同時間帯のセッションが

と激戦区すぎる…
こんなタイムテーブルにしたJJUGをdisるネタ*1も用意させていただきました。

実際はちゃんと画像とか貼ってましたが、まあいいや。

正直なところ私のセッションには、10人程度集まればよいかなと思っていました。
しかし、蓋を開けてみれば満員御礼*2!ありがたいことです。
内容として、プログラミングではなく、構築・運用系の話でしたが、他にそのようなセッションがあまりなかったので、よかったのかもしれません。

セッション途中で、Javaエバンジェリストの寺田さん([twitter:@yoshioterada])から指摘をいただいた件だけ、少し補足しておきます。
ファイルディスクリプタ(FD)の数は、経験則的に8192程度あれば足りるとは思うのですが、今後のアプリケーションとして、WebSocketを利用すると確かに足りなくなりそうですね。その場合でもリソース制限*3をかけた方がよいと思います。
ちなみにオープンしているFDについては、lsofとか使って確認してください。

また、本日になってからの反響が大きいのに驚きました。
スライドのページビュー数が増えてきたなと思ったら、はてブホッテントリ入りしたようです。
コメントも、今のところ批判などはないようでホッとしています。^^;
ページビューもおかげさまで順調に増え、5,000程度とすごい伸びで、興味を持っていただいた方も多いようです。

発表の場を設けていただいたJJUG運営の方々、ありがとうございました。

ちなみに懇親会LTで話したNative Memory Trackingのスライドも載せておきますね。
これも面白い機能だと思っています。

*1:あくまでネタですよ ^^;

*2:部屋のキャパシティ的に70名程度かと思います。

*3:WebLogicの実装はJSR-356に今のところ未対応ですが、最大コネクション数とかは簡単に制御できます。

WLSTでゆとりライブラリ作成 #yutori_history

この記事はゆとりアドベントカレンダーの3日目です。
寿司につられて参加してしまいました。私はイワシが好きです。よろしくお願いします。

それでは、本題に行ってみましょう。
相変わらずのWebLogicネタくらいしかないのですが、ゆとりさんに最初に捕捉されたお会いしたのは、WebLogic Server勉強会だったと思いますので、お許し下さい。

まず、WLSTはWebLogic Scripting Toolの略で、PythonJava実装であるJythonを利用して、WebLogic Serverの管理や監視などを行えます。
詳細はマニュアルを参照ください。

WLSTを実行した際に、共通で利用できるライブラリを簡単に作成してみましょう。
*1/common/wlst/lib に yutori.py を配置します。

(yutori.py)

print 'ゆとりさんのおごりで寿司が食べたい'

def tweet():
	print '#カオスな鯛'

def laugh():
	print 'ハッハッハー'

さて、呼び出してみましょう。

のどちらかでWLSTを実行できます。

WebLogic Scripting Tool(WLST)を初期化しています...

ゆとりさんのおごりで寿司が食べたい
WebLogic Server Administration Scripting Shellへようこそ

使用可能なコマンドに関するヘルプを表示するには、help()と入力してください

wls:/offline> yutori.tweet()
#カオスな鯛
wls:/offline> yutori.laugh()
ハッハッハー

これでいつでもゆとりさんを呼び出せます。

次は株式会社サムライズム代表取締役である[twitter:@yusuke]氏が何かを書いてくれるはずです。

*1:WebLogic Serverのホームディレクトリ。"/opt/oracle/middleware/wlserver_12.1"のようなディレクトリになります。

WebLogicのExpressモード

はじめに

この記事はJPOUG Advent Calendarの22日目です。
昨日は[twitter:@kingyokkun]さんによる"DWHっぽい事でも書いてみる"でした。
明日はロジ子さん([twitter:@OraBlogs_jp])の登場です。
私からはミドルウェア関連のネタを取り上げたいと思います。

本文

かつてBEA社の時代は、WebLogic Server(以下WLS)のエディションとして、WebLogic Express(通称:WLX)がありました。
これは実際に機能が限定されており、ServletコンテナなどJava EEの一部機能を提供するものでした。

Oracle社製品になってからは、Expressエディションはなくなり、異なるエディション体系(Standard/Enterprise/Suite)に変わりました。
これらは基本的に同一インストールバイナリ*1であり、ライセンスに基いて利用する機能を選択するようになっています。*2

さて、このようにバイナリとしては単一になったものの、実はオプションを指定することで、かつてのWebLogic Expressと同様にランタイムの機能制限を加えて起動することができます。
やり方は非常に簡単。起動オプションとして以下を加えるだけです。

-DserverType=wlx
起動

では簡単にですが試してみましょう。やり方は色々ありますが、設定変更を簡単に試すために環境変数JAVA_OPTIONSを設定して起動します。
DOMAIN_HOME環境変数はお使いのWLSドメインディレクトリに合わせて設定ください。

  • Unix環境の場合
cd $DOMAIN_HOME
JAVA_OPTIONS="-DserverType=wlx"
export JAVA_OPTIONS
./startWebLogic.sh 
cd %DOMAIN_HOME%
set JAVA_OPTIONS=-DserverType=wlx
startWebLogic.cmd
管理コンソールから見た変更点

さて、何が変わったのでしょう。
管理コンソール(デフォルト http://:7001/console/)にログインしてみましょう。

これだけだと分かりませんね。では通常の画面コピーと比較してみましょう。

はい、メッセージング関連のサービスが消えているのが分かりますね。左側のドメイン構造から辿っても同様です。

マニュアル

これは隠し機能ではなく、マニュアルにも記載されています。

通常、WebLogic Serverインスタンスの起動時には、EJB、JMS、コネクタ、クラスタリング、デプロイメント、管理などすべてのサービスが起動します。ただし、WebLogic Serverに備わっている起動オプションを使用した場合には、これらのサービスの一部を起動対象から除外して、ランタイム範囲を軽量化できます。この起動モードを使用すると、WebLogic Serverの起動時間が短くなり、ホスト・マシンのリソース範囲が小さくなります。

WebLogic Serverインスタンスで起動対象とするサービス群は、サーバー・タイプ・オプションを取るServer Type起動コマンドで定義します。このリリースには、次の2種類のサーバー・タイプ・オプションがあります。

WebLogic Serverインスタンスでこれらのサービスを使用する必要がない場合、軽量化ランタイムを実行するとパフォーマンスが大幅に向上する可能性があります。

WebLogic Server起動時のランタイム使用量の制限
serverTypeに指定できる値

マニュアルには"wlx"だけでなく"wls"も指定できるとありますが、実際にWLS12.1.1でやってみても起動時に警告が出力されてしまいます。

<2012/12/22 18時07分50秒 JST> <Warning> <Server> <BEA-002641> <-DserverTypeは認識されない値に設定されています: wls。サーバーはすべてのサービスが有効な状態で起動します。> 

ただ、無効なタイプを指定すると、すべてのサービスが有効となるため結果的には同様です。
この辺りを調べたところ、どうやら$WL_HOME/server/lib/service-config.propertiesで定義されている内容に基づいているようです。

# SERVICES
connector weblogic.t3.srvr.servicegroups.ConnectorServiceGroup
ejb weblogic.t3.srvr.servicegroups.EJBServiceGroup
jms weblogic.t3.srvr.servicegroups.JMSServiceGroup

# SERVER CONFIGS
wlx-config ejb jms connector

これを変更すれば、カスタムのserverTypeも定義できそうですが、当然ながらサポート対象外となりますので、商用環境ではやめましょう。

まとめ

  • WebLogic Server 12cはJava EE 6のFull Profile互換製品*3ですが、「-DserverType=wlx」を付加して起動することでWeb Profileと似たような*4起動ができます。

*1:プラットフォーム別のインストーラやZIP版もありますが、今回の趣旨とは異なるため、詳細は割愛します。

*2:紳士協定に基づくものであり、ライセンス外の機能も利用しようと思えばできてしまう訳ですが、当然ながらライセンス違反となります。

*3:Java EE Compatibility参照

*4:ちゃんと調べていないので、後で調べて更新する予定です。

WebLogic Server 12.1.1 on Mac OS X

はじめに

この記事はJavaEE Advent Calendar 2012の9日目です。
昨日は[twitter:@tt4cs]さんによる"http://tt4cs.blogspot.jp/2012/12/something-about-ldap-realm.html"でした。
明日は[twitter:@mike_neck]さんの登場となります。

私のネタは、若干今更感もありますが「WebLogic Server(以下、WLS)12cをMac OS Xで動かしてみよう」です。
WLS12.1.1では、開発用途ながらMac OS Xが正式にサーティファイされるようになりました。*1

[いきなり余談] WLSはOracle社の製品になってから、商用で利用するための開発ライセンスがしばらく存在しなかったのですが、近頃はOTN Free Developer Licenseも利用できるようになっています。
詳細は[twitter:@OraBlogs_jp]さんの"Oracle Blogs 日本語のまとめ: [WLS] WebLogic Application Server: free for developers!"を参照ください。

上記を参照する限り、今のところ環境としては

のみサーティファイされていますが、今回は環境含め、様々なパターンで検証してみることにしました。
※注意事項: 動作保証外の環境についての検証は正式なものではないので、Oracle社や製品サポートへのお問い合わせはご遠慮ください。

検証パターン

今回試してみたのは、以下の組み合わせです。

項目 内容
OS
  • OS X v10.7 Lion(10.7.5)
JDK
インストーラ
インストールモード
  • グラフィカル・モード
  • コンソール・モード
  • サイレント・モード


まずは、それぞれの項目について解説していきましょう。

OS
  • OS X v10.7 Lion
    • 正確なバージョンは10.7.5となります。
    • Mountain Lionでなくてごめんなさい。WLS12.1.2が出たらアップグレードして試したいとは思っています…


JDK
  • Apple HotSpot JDK 1.6.0_37(以下、Apple JDK6)
    • 説明: OS X v10.7 LionではOSにバンドルされており、OSアップデートにより最新版になっていましたので、これを利用することにしました。
    • 入手方法: バンドルされていない場合、Apple Developer Downloadsから「Java」で検索してダウンロードできます。
    • JDKホーム: /System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home

[余談その2] 10/16に公開されたOS X向けJavaのセキュリティアップデート「Java for OS X 2012-006」を入れたことで「Java Preferences」がなくなったようで戸惑いました。*4
Oracle JDKでは[システム環境設定]-[その他]-[Java]から「Javaコントロール・パネル」を利用することになります。


インストーラ

Oracle Fusion Middleware 11g ソフトウェア・ダウンロードからダウンロードできるインストーラのうち、OS Xで利用できるのは、以下となります。

  • Zip for Windows x86, Linux x86, Mac OS X(以下、ZIP版)
    • 説明: ZIPファイルを展開後いくつかの手順によりセットアップするインストーラです。容量は他のインストーラと比較して最小ですが、いくつか制限事項があります。詳細はZIPファイル内のREADME.txtを参照ください。
    • ファイル名: wls1211_dev.zip
    • サイズ: 183MB
  • Generic Installer(以下、Generic版)
    • 説明: OSに基本的に依存しないインストーラです。通常は64bit JDKを利用する場合に使用します。
    • ファイル名: wls1211_generic.jar
    • サイズ: 997MB

インストールモード

ZIP版の場合は関係ありませんが、OS X専用版とGeneric版のインストーラでは3つのモードがあります。
JDKホームを$JAVA_HOME、インストーラファイル名を$INSTALLER_JARとして、基本的な実行方法についても説明します。詳細は各マニュアルを参照ください。

以下にサイレント用のXMLファイル(上記$SILENT_XML)の例を示します。

<?xml version="1.0" encoding="UTF-8"?>
<bea-installer>
  <input-fields>
    <data-value name="BEAHOME" value="/Users/xxx/Oracle/Middleware" />
    <data-value name="WLS_INSTALL_DIR" value="/Users/xxx/Oracle/Middleware/wlserver_12.1" />
    <data-value name="COMPONENT_PATHS"
        value="WebLogic Server/Core Application Server|WebLogic Server/Administration Console|WebLogic Server/Configuration Wizard and Upgrade Framework|WebLogic Server/Web 2.0 HTTP Pub-Sub Server|WebLogic Server/WebLogic JDBC Drivers|WebLogic Server/Third Party JDBC Drivers|WebLogic Server/WebLogic Server Clients|WebLogic Server/Xquery Support|Oracle Coherence/Coherence Product Files" />
    <data-value name="LOCAL_JVMS" value="/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home" />
  </input-fields>
</bea-installer>

検証結果

まずは結論から。以下のマトリックスを参照ください。

ZIP版OS X専用版Generic版
OSJDKGUICUISilentGUICUISilent
10.7Apple JDK6×
Oracle JDK7××××××
: ほぼ問題なくインストール可能
: 若干の難ありだが、インストール可能
× : インストール不可

項目ごとのポイント

すべてのパターンを網羅的に説明すると膨大になってしまうので、項目ごとに説明していきます。
それでも非常に長くなるため、最後のまとめへ飛んでいただいて構いません…

JDK
  • Apple JDK6
    • OS X専用版やGeneric版のインストーラを使用するときは、Apple JDK6を利用するのがよいです
    • CUIモードでのインストールやドメイン作成時、WLS起動時に日本語環境では文字化けします。これを防ぐためには"LC_ALL=C; export LC_ALL"してから実行します。*5
  • Oracle JDK7
    • ZIP版であれば問題なくインストールできますが、全体的にOS X専用版やGeneric版のインストーラとの相性がよくありません。WLS12.1.2ではこの辺りも改善されることを期待しています。
    • Apple JDK6とは逆に、LANGやLC_ALL環境変数をCに設定すると文字化けしてしまいました。ja_JP.UTF-8のままが無難なようです。
    • GUIモードで起動するとウィザード画面が[終了]しか押せないほど、極端に小さくなり進めなくなります。

    • CUIモードやSilentモードで進めても、実際のインストール時にエラーになってしまいます。
      • Silentモードでのエラー例
Extracting scripts to /var/folders/fv/xxx/T/
Executing MacOS-specific pre-installation scripts
Extracting 0%....................................................................................................100%
log4j:WARN Failed to set property conversionPattern to value "%d [%t] %-5p - %m%n". null
log4j:WARN Failed to set property conversionPattern to value "%d [%t] %-5p - %m%n". null
ファイルのインストール中に致命的なエラーが発生しました。インストーラはクリーン・アップして終了します。
    • OS X専用版と組み合わせる際、-logオプションをつけると以下のエラーになってしまいます。Generic版と組み合わせた場合でも"-Dos.name=unix"(後述)を付加すると同じエラーになるため、これらの条件下では詳細なログを取得できません。
Exception in thread "main" java.lang.AssertionError: Platform not recognized
	at sun.nio.fs.DefaultFileSystemProvider.create(DefaultFileSystemProvider.java:73)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.getDefaultProvider(FileSystems.java:108)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.access$000(FileSystems.java:89)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:98)
	at java.nio.file.FileSystems$DefaultFileSystemHolder$1.run(FileSystems.java:96)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.defaultFileSystem(FileSystems.java:95)
	at java.nio.file.FileSystems$DefaultFileSystemHolder.<clinit>(FileSystems.java:90)
	at java.nio.file.FileSystems.getDefault(FileSystems.java:176)
	at sun.util.calendar.ZoneInfoFile$1.run(ZoneInfoFile.java:483)
	at sun.util.calendar.ZoneInfoFile$1.run(ZoneInfoFile.java:478)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.util.calendar.ZoneInfoFile.<clinit>(ZoneInfoFile.java:477)
	at sun.util.calendar.ZoneInfo.getTimeZone(ZoneInfo.java:663)
	at java.util.TimeZone.getTimeZone(TimeZone.java:571)
	at java.util.TimeZone.setDefaultZone(TimeZone.java:668)
	at java.util.TimeZone.getDefaultRef(TimeZone.java:635)
	at java.util.TimeZone.getDefault(TimeZone.java:622)
	at java.text.SimpleDateFormat.initializeCalendar(SimpleDateFormat.java:682)
	at java.text.SimpleDateFormat.<init>(SimpleDateFormat.java:581)
	at java.text.MessageFormat.makeFormat(MessageFormat.java:1496)
	at java.text.MessageFormat.applyPattern(MessageFormat.java:479)
	at java.text.MessageFormat.<init>(MessageFormat.java:363)
	at com.bea.plateng.common.util.logging.Jdk14Logger$DefaultFormatter.<init>(Jdk14Logger.java:404)
	at com.bea.plateng.common.util.logging.Jdk14Logger$DefaultFormatter.<init>(Jdk14Logger.java:416)
	at com.bea.plateng.common.util.logging.Jdk14Logger.addDestination(Jdk14Logger.java:350)
	at com.bea.plateng.wizard.WizardController.setupWizardLog(WizardController.java:373)
	at com.bea.plateng.wizard.WizardController.<init>(WizardController.java:168)
	at com.bea.plateng.wizard.WizardHelper.invokeWizard(WizardHelper.java:161)
	at com.bea.plateng.wizard.WizardHelper.invokeWizardAndWait(WizardHelper.java:42)
	at com.bea.plateng.wizard.WizardController.main(WizardController.java:933)
インストーラ
  • OS X専用版
    • Apple JDK6であればGUIモードでも動作しますGUIモードでの注意点は後述します。
    • CUIモードでは起動はするけど、最初の画面から次へまったく進めません。
[~]$ LC_ALL=C; export LC_ALL
[~]$ $JAVA_HOME/bin/java -jar $INSTALLER_JAR -mode=console
Extracting scripts to /var/folders/fv/xxx/T/
Executing MacOS-specific pre-installation scripts
Extracting 0%....................................................................................................100%




<----------- Oracle Installer - Oracle Enterprise Pack for Eclipse ----------->

Welcome:
--------

This installer will guide you through the installation of Oracle Enterprise 
Pack for Eclipse. Type "Next" or enter to proceed to the next prompt.  If you 
want to change data entered previously, type "Previous".  You may quit the 
installer at any time by typing "Exit".




Enter [Exit][Next]> Next

スレッドダンプを取得すると、ファイル読み込み待ちのまま延々と待っていますが、何のファイルかは不明です。

"Console Controller" daemon prio=5 tid=0x00007fa365057800 nid=0x4b03 runnable [0x000000010d34b000]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileInputStream.readBytes(Native Method)
	at java.io.FileInputStream.read(FileInputStream.java:242)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:273)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
	- locked <0x00000007f6d822d8> (a java.io.BufferedInputStream)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177)
	- locked <0x00000007f6d86388> (a java.io.InputStreamReader)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.BufferedReader.fill(BufferedReader.java:154)
	at java.io.BufferedReader.readLine(BufferedReader.java:317)
	- locked <0x00000007f6d86388> (a java.io.InputStreamReader)
	at java.io.BufferedReader.readLine(BufferedReader.java:382)
	at com.bea.plateng.wizard.ConsoleContext$ConsoleController.run(ConsoleContext.java:823)
	at java.lang.Thread.run(Thread.java:722)
  • Generic版
    • 通常のまま実行すると、ディスクの空き領域検出で失敗します。
Extracting 0%....................................................................................................100%
Insufficient disk space! The installer requires:
185MB for the BEA Home at /Users/xxx/Oracle/Middleware,
294MB for the product at /Users/xxx/Oracle/Middleware/coherence_3.7,/Users/xxx/Oracle/Middleware/utils/uninstall/WebLogic_Platform_12.1.1.0,/Users/xxx/Oracle/Middleware/wlserver_12.1 and
1071MB temporary work space at /var/folders/fv/xxx/T/beaxxx.tmp.
There is only 1MB available at /Users/xxx/Oracle/Middleware/wlserver_12.1.
    • -logオプションで取得したログを確認すると"ERROR:unknown OS"とみなされていることが分かります。
2012-12-09 17:38:30,025 ERROR [WizardController] com.bea.plateng.common.util.DetectFreeSpace - INSTALLER ERROR:unknown OS
インストールモード
  • GUIモード
    • 前述のようにApple JDK6であれば動作します。
    • [セキュリティ更新のための登録]画面で、多少つまづくかもしれません。
      ここで[セキュリティ更新をMy Oracle Supportから受け取ります]のチェックを外そうとしても外せないように見えますが、無視して[次へ]をやって何度かステップを踏むと先に進めます。
      マニュアルにも記載されています。

    • [JDKの選択]画面でJDKを指定することができます。以降、WLSドメインを作成するときにもJDKを指定できますが、JDK7を利用したい場合、ここで指定しておくのが楽です。


  • CUIモード
    • Apple JDK6では文字化けするので、前述のように"LC_ALL=C; export LC_ALL"してから実行してください。
      また、日本語環境だとウィザード画面でPreviousやExitが効かず、先にしか進めません。
      • この場合、インストールを行わず終了するにはCtrl+Cで強制停止するしかありません。
        そうするとクリーンアップが行われないので、一時フォルダ(デフォルトで、/var/folders/fv/xxx/T/beaxxxのようになる)を適宜削除してください。
  • Silentモード
    • ターミナル上は進行状況が分からなく不安になるので、実行時に-logオプションを付加してログを取得した方がよいです。ログには警告(WARN)がかなり出力されますが、最後に以下のように出力されていれば問題ありません。
2012-12-09 17:48:19,546 INFO  [WizardController] com.bea.plateng.wizard.silent.tasks.LogTask - The installation was successfull!

インストール後

ドメイン作成
  • インストールが正常に完了すれば、ドメインの作成などは問題なく行えます。
    • ドメイン構成ウィザードはインストール後のQuickStartから起動できます。それ以降に作成する場合は"$WL_HOME/common/bin/config.sh"を実行してください。


  • ドメイン作成時に「本番モード」を指定したときは、WLS起動前に別途boot.propertiesを事前作成してください。
    • boot.propertiesの詳細については、以前にWebLogic Server勉強会発表した資料を参照ください。
    • 通常は起動時にパスワードを入力できますが、Mac用のネイティブライブラリがないため、パスワードを安全に入力できないとみなされるからです。
<2012/12/09 17時51分55秒 JST> <Info> <Security> <BEA-090065> <ユーザーから起動アイデンティティを取得しています。> 
WebLogic Serverを起動するためのユーザー名を入力してください:weblogic
<2012/12/09 17時51分58秒 JST> <Error> <Security> <BEA-090782> <サーバーは本番モードで実行されています。コマンドラインからパスワードを安全に読み取るためのネイティブ・ライブラリ(terminalio)が見つかりません。> 
<2012/12/09 17時51分58秒 JST> <Notice> <WebLogicServer> <BEA-000388> <JVMによりWebLogic Serverの停止フックが呼び出されました。サーバーは強制停止されます。> 
<2012/12/09 17時51分58秒 JST> <Alert> <WebLogicServer> <BEA-000396> <<WLS Kernel>からサーバーをshutdownするようリクエストされました。> 
<2012/12/09 17時51分58秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がFORCE_SHUTTING_DOWNに変化しました。> 
起動
  • ドメイン作成後はWLSを起動しましょう。"$DOMAIN_HOME/bin/startWebLogic.sh"を実行してください。
    • 専用のネイティブライブラリがMac版にはありませんのでいくつか警告が出力されますが、開発用途なので特に無視して問題ないはずです。
	.
	.
	JAVA Memory arguments: -Xms256m -Xmx512m -XX:CompileThreshold=8000 -XX:PermSize=128m  -XX:MaxPermSize=256m
	.
	WLS Start Mode=Development
	.
	CLASSPATH=/Users/xxx/Oracle/Middleware/patch_wls1211/profiles/default/sys_manifest_classpath/weblogic_patch.jar:/Users/xxx/Oracle/Middleware/patch_ocp371/profiles/default/sys_manifest_classpath/weblogic_patch.jar:/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/lib/tools.jar:/Users/xxx/Oracle/Middleware/wlserver_12.1/server/lib/weblogic_sp.jar:/Users/xxx/Oracle/Middleware/wlserver_12.1/server/lib/weblogic.jar:/Users/xxx/Oracle/Middleware/modules/features/weblogic.server.modules_12.1.1.0.jar:/Users/xxx/Oracle/Middleware/wlserver_12.1/server/lib/webservices.jar:/Users/xxx/Oracle/Middleware/modules/org.apache.ant_1.7.1/lib/ant-all.jar:/Users/xxx/Oracle/Middleware/modules/net.sf.antcontrib_1.1.0.0_1-0b2/lib/ant-contrib.jar:/Users/xxx/Oracle/Middleware/wlserver_12.1/common/derby/lib/derbyclient.jar:/Users/xxx/Oracle/Middleware/wlserver_12.1/server/lib/xqrl.jar
	.
	PATH=/Users/xxx/Oracle/Middleware/wlserver_12.1/server/bin:/Users/xxx/Oracle/Middleware/modules/org.apache.ant_1.7.1/bin:/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/jre/bin:/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/bin:/usr/bin:/bin:/usr/sbin:/sbin:/usr/local/bin:/usr/X11/bin
	.
	***************************************************
	*  To start WebLogic Server, use a username and   *
	*  password assigned to an admin-level user.  For *
	*  server administration, use the WebLogic Server *
	*  console at http://hostname:port/console        *
	***************************************************
	starting weblogic with Java version:
	java version "1.7.0_09"
	Java(TM) SE Runtime Environment (build 1.7.0_09-b05)
	Java HotSpot(TM) 64-Bit Server VM (build 23.5-b02, mixed mode)
	Starting WLS with line:
	/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/bin/java -client   -Xms256m -Xmx512m -XX:CompileThreshold=8000 -XX:PermSize=128m  -XX:MaxPermSize=256m -Dweblogic.Name=AdminServer -Djava.security.policy=/Users/xxx/Oracle/Middleware/wlserver_12.1/server/lib/weblogic.policy  -Xverify:none -Djava.endorsed.dirs=/Library/Java/JavaVirtualMachines/jdk1.7.0_09.jdk/Contents/Home/jre/lib/endorsed:/Users/xxx/Oracle/Middleware/wlserver_12.1/endorsed  -da -Dplatform.home=/Users/xxx/Oracle/Middleware/wlserver_12.1 -Dwls.home=/Users/xxx/Oracle/Middleware/wlserver_12.1/server -Dweblogic.home=/Users/xxx/Oracle/Middleware/wlserver_12.1/server   -Dweblogic.management.discover=true  -Dwlw.iterativeDev= -Dwlw.testConsole= -Dwlw.logErrorsToConsole= -Dweblogic.ext.dirs=/Users/xxx/Oracle/Middleware/patch_wls1211/profiles/default/sysext_manifest_classpath:/Users/xxx/Oracle/Middleware/patch_ocp371/profiles/default/sysext_manifest_classpath  weblogic.Server
	<2012/12/09 18時43分07秒 JST> <Info> <Security> <BEA-090905> <起動パフォーマンスを向上するためにCryptoJ JCEプロバイダ自己整合性チェックを無効にしています。このチェックを有効にするには、-Dweblogic.security.allowCryptoJDefaultJCEVerification=trueを指定します> 
	<2012/12/09 18時43分08秒 JST> <Info> <Security> <BEA-090906> <RSA CryptoJのデフォルトの乱数ジェネレータをECDRBGからFIPS186PRNGに変更しています。この変更を無効にするには、-Dweblogic.security.allowCryptoJDefaultPRNG=trueを指定します> 
	<2012/12/09 18時43分08秒 JST> <Info> <WebLogicServer> <BEA-000377> <WebLogic ServerをOracle CorporationからJava HotSpot(TM) 64-Bit Server VMバージョン23.5-b02で起動しています。> 
	<2012/12/09 18時43分09秒 JST> <Info> <Management> <BEA-141107> <バージョン: WebLogic Server Temporary Patch for 13340309 Thu Feb 16 18:30:21 IST 2012
	WebLogic Server Temporary Patch for 13019800 Mon Jan 16 16:53:54 IST 2012
	WebLogic Server Temporary Patch for BUG13391585 Thu Feb 02 10:18:36 IST 2012
	WebLogic Server Temporary Patch for 13516712 Mon Jan 30 15:09:33 IST 2012
	WebLogic Server Temporary Patch for BUG13641115 Tue Jan 31 11:19:13 IST 2012
	WebLogic Server Temporary Patch for BUG13603813 Wed Feb 15 19:34:13 IST 2012
	WebLogic Server Temporary Patch for 13424251 Mon Jan 30 14:32:34 IST 2012
	WebLogic Server Temporary Patch for 13361720 Mon Jan 30 15:24:05 IST 2012
	WebLogic Server Temporary Patch for BUG13421471 Wed Feb 01 11:24:18 IST 2012
	WebLogic Server Temporary Patch for BUG13657792 Thu Feb 23 12:57:33 IST 2012
	WebLogic Server 12.1.1.0  Wed Dec 7 08:40:57 PST 2011 1445491 > 
	<2012/12/09 18時43分10秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がSTARTINGに変化しました。> 
	<2012/12/09 18時43分10秒 JST> <Info> <WorkManager> <BEA-002900> <自動チューニング・スレッド・プールを初期化しています。> 
	<2012/12/09 18時43分10秒 JST> <Notice> <Log Management> <BEA-170019> <サーバー・ログ・ファイル/Users/xxx/Oracle/Middleware/user_projects/domains/base_domain/servers/AdminServer/logs/AdminServer.logを開きました。すべてのサーバーサイド・ログ・イベントはこのファイルに書き込まれます。> 
	<2012/12/09 18時43分10秒 JST> <Error> <Socket> <BEA-000438> <パフォーマンス・パックをロードできません。かわりにJava I/Oを使用しています。Please ensure that libmuxer library is in :'/Users/xxx/Oracle/Middleware/patch_wls1211/profiles/default/native:/Users/xxx/Oracle/Middleware/patch_ocp371/profiles/default/native:/Users/xxx/Oracle/Middleware/wlserver_12.1/server/native/macosx:/Users/xxx/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:.'
	> 
	<2012/12/09 18時43分13秒 JST> <Notice> <Security> <BEA-090082> <セキュリティはセキュリティ・レルムmyrealmを使用して初期化しています。> 
	<2012/12/09 18時43分14秒 JST> <Warning> <Store> <BEA-280109> <永続ファイル・ストア"_WLS_AdminServer"のネイティブのwlfileioライブラリをロードできません。ストアはバッファされたI/Oを使用します。ストアは、まだトランザクション上安全な同期モードで動作しています。リクエストされた書込みポリシーおよび最終的な書込みポリシーを調べるには、ストアのオープン・ログ・メッセージを参照してください。> 
	<2012/12/09 18時43分15秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がSTANDBYに変化しました。> 
	<2012/12/09 18時43分15秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がSTARTINGに変化しました。> 
	<2012/12/09 18時43分15秒 JST> <Notice> <Log Management> <BEA-170027> <サーバーはドメイン・レベルの診断サービスとの接続を正常に確立しました。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がADMINに変化しました。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がRESUMINGに変化しました。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <Server> <BEA-002613> <チャネル"Default"は、現在127.0.0.1: 7001でプロトコルiiop, t3, ldap, snmp, httpをリスニングしています。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <WebLogicServer> <BEA-000331> <ドメイン"base_domain"で、WebLogic Server管理サーバー"AdminServer"を開発モードで起動しました。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <WebLogicServer> <BEA-000365> <サーバー状態がRUNNINGに変化しました。> 
	<2012/12/09 18時43分16秒 JST> <Notice> <WebLogicServer> <BEA-000360> <サーバーがRUNNINGモードで起動しました。> 
管理コンソール
  • ブラウザから「http://:/console/」で管理コンソールにアクセスできます。
    • ポート番号はログにも出力されますが、デフォルトは「7001」です。


まとめ

  • WLS12cは開発用途でなら、Mac OS Xでも利用できます。是非ご利用ください。
  • Mac OS Xで動かすならZIP版が簡単です。OS X専用版やGeneric版のインストーラを使用するときは、動作保証されているApple JDK6で動かすのがよいです。
  • WLS12.1.2で、(Mountain)LionやOracle JDK7(できればOpenJDK)も正式にサーティファイされるといいですね。

*1:WLS10.3での非公式ハックは[twitter:@yusuke]さんの"http://samuraism.jp/diary/2008/09/20/1221842883416.html"を参照ください。

*2:Certification Matrixには10.3.6と記載されていますが、10.6が正しいはずです。

*3:Oracle JDK7のインストール場所が、"which java"などでは分からず"find / -name java"で探してしまいました。詳細は[twitter:@aoetk]さんの"謎なMacのJavaインストール構成 - AOEの日記"を参照ください。

*4:Java Preferences」がなくなった経緯は"「JavaはOracleから直接入手を」、Apple経由のプラグインに削除措置 - ITmedia エンタープライズ"を参照ください。

*5:Unix系OSではLANG環境変数に設定するのが一般的な解決策だと思いますが、LC_ALLに設定する必要がありました。localeコマンドを実行しても他のLC_*系変数が悪さをしてるようには見えず、よく分かってません…

Oracle ACE(ミドルウェア分野)に認定されました!

社内など限られた方には話していたのですが、そろそろ解禁でいいですかね。
この度、Oracle ACEメンバーとして認定いただきました。
Oracle ACE 概要

日本では十数人(ミドルウェア分野では二人目)、世界では400人程度(同60人程度)のようです。
正直、私なんぞが認定されるのは恥ずかしい限りですが、周囲の皆様のご支援があってこそと考えております。
今後も精進して参りますので、よろしくお願い致します。


JavaマスコットのDuke、社員犬キャンディ、キティ(向かって左がACE記念)


Duke関連グッズ(シールとコースターがACE記念)