Sunday, 17 May 2009

Weblogic - Socket Muxers in Thread Dumps

What are these weblogic.socket.Muxer threads seen in thread dumps ?

Note: for a basic primer on taking thread dumps and analyzing them, see this earlier article

Socket Reader Threads accept the incoming request from the Listen Thread Queue and put it on the Execute Thread Queue.

In WL 8.1, there are 3 socket reader threads by default.
In WL 9 and 10, WebLogic allocates 33% of server threads to act as socket readers by default. This need not be changed usually.

One socket reader thread is usually in the poll function, while the others are available to process requests.
The polling thread is highlighted in the thread dump below.


"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x016b2148 nid=0x42 waiting for monitor entry [5997f000..5997fc28]
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)
- waiting to lock <0x94846b40> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)


"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x00683c28 nid=0x41 waiting for monitor entry [59a7f000..59a7fc28]
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)
- waiting to lock <0x94846b40> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)


"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x0079e5b0 nid=0x40 runnable [59b7f000..59b7fc28]
at weblogic.socket.PosixSocketMuxer.poll(Native Method)
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:100)
- locked <0x94846b40> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)



In an earlier support case on Stuck Threads, we asked BEA:

Should we worry about the Weblogic.socket.Muxer threads which always show 2 threads waiting for lock and 3rd thread locking the same object?

The Muxer TD is attached. This shows same behaviour on all our Weblogic servers.


Full thread dump Java HotSpot(TM) Server VM (1.4.2_05-b04 mixed mode):

"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x0151
c588 nid=0x1b4 waiting for monitor entry [ad57f000..ad57fc28]
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)
- waiting to lock <0xd9331760> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)



"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x0161
d608 nid=0x1b3 runnable [ad67f000..ad67fc28]
at weblogic.socket.PosixSocketMuxer.poll(Native Method)
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:100)
- locked <0xd9331760> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)



"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" daemon prio=5 tid=0x01bb
6730 nid=0x1b2 waiting for monitor entry [ad77f000..ad77fc28]
at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)
- waiting to lock <0xd9331760> (a java.lang.String)
at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:32)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:219)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:178)



The reply from BEA Support was that the above pattern of weblogic.socket.Muxer threads are not a cause of stuck threads.


Why do they mostly show as being Stuck in Samurai TD analyzer ?




As the image shows, when you analyze thread dumps using Samurai, the muxer threads are shown as being Stuck since they're all locked on the same object. This is probably treated as a deadlock condition.


"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'"
- waiting to lock <0xd9b61098> (a java.lang.String)


"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'"
- waiting to lock <0xd9b61098> (a java.lang.String)


"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'"
- locked <0xd9b61098> (a java.lang.String)



But you will see the same in any Thread dump even on a development instance with no requests.
The locks mentioned do show up as red in Samurai - but they aren't deadlocks just regular locks.

A thread gains an exclusive lock on an object to perform some action, then frees it allowing the next thread to gain access.

Additionally, if you look at the thread dumps over time, you'll see that these specific locks are not always present - they are moving between the threads which is indicative of their transitory nature.



I want to know more details on Muxers


The socket Muxer manages the server’s existing socket connections.
It first determines which sockets have incoming requests waiting to be processed. It then reads enough data to determine the protocol and dispatches the socket to an appropriate runtime layer based on the protocol.
In the runtime layer, the socket muxer threads determine which execute thread queue to be used and delegates the request accordingly.

From the documentation on http://edocs.bea.com/wls/docs100/perform/WLSTuning.html#wp1152246 ,
Weblogic has two versions of the socket muxer, one is the Java version and the other uses a native library which makes better use of operating system calls. The Enable Native IO checkbox on the server’s configuration settings tells the server which version to use. This is ON by default for most platforms.

Native muxers provide superior scalability because they implement a non-blocking thread model. When a native muxer is used, the server creates a fixed number of threads dedicated to reading incoming requests. Oracle recommends using the default setting of true for the Enable Native IO parameter which allows the server to automatically select the appropriate muxer to use.

You must ensure that to use Native I/O, the native library must be present in the server’s shared library path . This is set up with the default scripts.
When the server does not find the native library, it throws an error
java.lang.UnsatisfiedLinkError: no muxer in java.library.path
and then loads the Java version of the muxer.

Confirm the LD library path is okay and pointing to the Solaris LD path. Check the startup log when starting a managed server. What is the value of java.library.path?
This is where the JVM actually get's the library from.

http://m-button.blogspot.com/2008/08/how-does-weblogic-handle-socket-muxers.html has a good example of how to identify Native vs Java muxer in a thread dump.

The Thread Dump I’ve used in my examples above uses the Native muxer (weblogic.socket.PosixSocketMuxer) on Solaris.

Solaris has another Native muxer called the weblogic.socket.DevPollSocketMuxer
An example TD using this muxer is shown below.


"ExecuteThread: '4' for queue: 'weblogic.socket.Muxer'" waiting for lock java.lang.String@4edf4f BLOCKED
weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:95)
weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)
weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)



"ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" RUNNABLE native
weblogic.socket.DevPollSocketMuxer.doPoll(Native Method)
weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:96)
weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)



weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)
"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" waiting for lock java.lang.String@4edf4f BLOCKED
weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:95)
weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)
weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)



"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" waiting for lock java.lang.String@4edf4f BLOCKED
weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:95)
weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)
weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)



"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" waiting for lock java.lang.String@4edf4f BLOCKED
weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:95)
weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)
weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)





To change the number of Muxers from the default, follow the instructions given at http://e-docs.bea.com/wls/docs92/ConsoleHelp/taskhelp/tuning/TuningSocketReaders.html




See http://jojovedder.blogspot.com/2009/07/more-on-weblogic-muxers.htmlfor an update on Muxers

Additionally on Oracle JRockit JVMs - there are some information in the thread dumps which point out the same problem in a different manner.

After the normal stack dumps, BEA JRockit performs a deadlock detection. This is done by finding "lock chains" in the Java application. If a lock chain is found to be circular, the application is considered caught in a deadlock.

A detailed explanation of the 3 types of lock chains in JRockit is given here


What is relevant for us is the example of Muxers which are shown as:


Blocked lock chains
===================
Chain 2:
"ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" id=129 idx=0x218 tid=4079 waiting for java/lang/String@0x37804000 held by:
"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=127 idx=0x210 tid=4077 in chain 1

Open lock chains
================
Chain 1:
"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=128 idx=0x214 tid=4078 waiting for java/lang/String@0x37804000 held by:
"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=127 idx=0x210 tid=4077 (active)


As per the explanation, the Open lock chain depicts Thread 1 waiting for Thread 0. This is not a deadlock, only a straight dependency.

Since Thread 0 is already part of the Open lock chain, the fact that Thread 2 is also waiting on the same Thread 0 is treated as a "Blocked lock chain".
In this case this is not a problem.

Update 15th Feb 2011

I'm glad this blog entry on weblogic muxers has made it onto the Oracle forums with a mention from James Bayer.

12 comments:

  1. Great clarification. I've got a situation where we have WL9 running and the weblogic.kernel.default queue grows out of control. When taking the thread dump and running it through an analyzer, it shows weblogic.socket.Muxer is deadlocked. Glad to hear its not because of that, but now i have to dig even deeper.

    ReplyDelete
  2. Thanks Kevin - I'm interested in seeing an example (if it is possible) where all the Muxer threads are showing blocked and none RUNNING.
    Anyone out there facing that problem, please drop a note.

    ReplyDelete
  3. Hi,
    Thanks for the article. What does it mean if in the same time two socket muxer thread runs, seen as green in samurai.

    ReplyDelete
  4. I have similar kind of problem

    Need your advise.

    "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=127 idx=0x210 tid=4077 prio=5 alive, in native, daemon     at weblogic/socket/PosixSocketMuxer.poll([Lweblogic/socket/PosixSocketInfo$FdStruct;I)Z(Native Method)     at weblogic/socket/PosixSocketMuxer.processSockets(PosixSocketMuxer.java:100)     ^-- Holding lock: java/lang/String@ 0x37804000[fat lock]     at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:32)     at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:224)     at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:183)     at jrockit/vm/RNI.c2java(IIIII)V(Native Method)     -- end of trace



    ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=128 idx=0x214 tid=4078 prio=5 alive, in native, blocked, daemon     -- Blocked trying to get lock: java/lang/String@0x37804000[fat lock]     at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)     at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1675)[optimized]     at jrockit/vm/Locks.lockFat(Locks.java:1776)[optimized]     at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1312)[optimized]     at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1259)[optimized]     at jrockit/vm/Locks.monitorEnter(Locks.java:2456)[optimized]     at weblogic/socket/PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)     at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:32)     at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:224)     at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:183)     at jrockit/vm/RNI.c2java(IIIII)V(Native Method)     -- end of trace


    "ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" id=129 idx=0x218 tid=4079 prio=5 alive, in native, blocked, daemon     -- Blocked trying to get lock: java/lang/String@0x37804000[fat lock]     at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)     at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1675)[inlined]     at jrockit/vm/Locks.fatLockReacquire(Locks.java:1913)[optimized]     at jrockit/vm/Locks.lockFat(Locks.java:1781)[optimized]     at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1312)[optimized]     at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1259)[optimized]     at jrockit/vm/Locks.monitorEnter(Locks.java:2456)[optimized]     at weblogic/socket/PosixSocketMuxer.processSockets(PosixSocketMuxer.java:91)     at weblogic/socket/SocketReaderRequest.execute(SocketReaderRequest.java:32)     at weblogic/kernel/ExecuteThread.execute(ExecuteThread.java:224)     at weblogic/kernel/ExecuteThread.run(ExecuteThread.java:183)     at jrockit/vm/RNI.c2java(IIIII)V(Native Method)     -- end of trace


    Blocked lock chains
    ===================
    Chain 2:
    "ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" id=129 idx=0x218 tid=4079 waiting for java/lang/String@0x37804000 held by:
    "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=127 idx=0x210 tid=4077 in chain 1

    Open lock chains
    ================
    Chain 1:
    "ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=128 idx=0x214 tid=4078 waiting for java/lang/String@0x37804000 held by:
    "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=127 idx=0x210 tid=4077 (active)

    ReplyDelete
  5. The muxer trace you have posted is similar to the one seen on Sun JVM in the post.
    Execute Thread 0 is polling and has a lock on "0x37804000". The other two threads are waiting for java/lang/String@0x37804000.

    Dont think these are Stuck

    ReplyDelete
  6. HI Could you please let me know these are dead lock situation :

    Thread Name : Execute Thread :'1' for queue: 'weblogic.socket.Muxer'
    State : Runnable
    Owns Monitor Lock on 0x99b07318
    Java Stack
    at weblogic.socket.PosixSocketMuxer.poll(Native Method)

    at weblogic.socket.PosixSocketMuxer.processSockets(PosixSocketMuxer.java:100)
    -locked [0x99b07318] (a java.lang.string)

    ReplyDelete
  7. Hi, couls you please suggest about this one

    Blocked lock chains
    ===================
    Chain 3:
    "ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=27 idx=0x68 tid=29142 waiting for java/lang/String@0x71dd7d30 held by:
    "ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" id=29 idx=0x70 tid=29144 in chain 2

    Chain 4:
    "ExecuteThread: '2' for queue: 'weblogic.socket.Muxer'" id=28 idx=0x6c tid=29143 waiting for java/lang/String@0x71dd7d30 held by:
    "ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" id=29 idx=0x70 tid=29144 in chain 2

    Open lock chains
    ================
    Chain 1:
    "Finalizer" id=7 idx=0x2c tid=29097 waiting for HTTPClient/StreamDemultiplexor@0x9b039cd0 held by:
    "[ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)'" id=205 idx=0x314 tid=30103 (active)

    Chain 2:
    "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=26 idx=0x64 tid=29141 waiting for java/lang/String@0x71dd7d30 held by:
    "ExecuteThread: '3' for queue: 'weblogic.socket.Muxer'" id=29 idx=0x70 tid=29144 (active)

    ReplyDelete
  8. I took three threadumps and each time the lock is being held at different thread of weblogic.socket.Muxer and the other two will wait for the lock which is held- it should be okay right?

    ReplyDelete
  9. Hi,

    Thanks for the useful blog, but I want to understand the relation between this configuration which exist at Each admin/managed server under tunning tab page which says % of thread pool can be used for socket reader, here is my concern -

    If for a managed server we have both below setting then which one will be true and active -

    1) -Dweblogic.SocketReaders=4

    2) Tunning tab page saying 33% of Execute Tread pool can be utilized for socket reader, since Execute thread max thread limit it not defined, and its runtime getting allocated, e.g. if the Execute Thread pool is showing 100 threads, does it means 33% of 100 means 33 threads getting used for socket reading, If yes then what is this setting -Dweblogic.SocketReaders=4? Are we restricting socket reader count using this configuration.

    I just want to understand the relation ship between this configuration -Dweblogic.SocketReaders=4 and the configuration exist at Tunning tab page for % of socket Reader threads.

    Regards..
    Manish

    ReplyDelete
  10. Manish,

    -Dweblogic.SocketReaders=4 will override the Tuning tab value.

    this is tested on Weblogic 12c

    ReplyDelete
  11. Good Post.. very useful.

    Thanks,
    www.wikiconsole.com

    ReplyDelete