BPEL Composite Under Load SOA 11.1.1.4: Stuck Threads and Deadlock Between Concurrent Threads Trying to Access a Schemamap (Doc ID 1334888.1)

<May 17, 2011 7:53:38 PM EDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK]
ExecuteThread: '162' for queue: 'weblogic.kernel.Default (self-tuning)' has
been busy for "603" seconds working on the request
"weblogic.servlet.internal.ServletRequestImpl@5a77cce4[
POST
/soa-infra/services/default/xxxx/<name>_client?WSDL
HTTP/1.1
Content-Type: text/xml; charset=utf-8
Cache-Control: no-cache
SOAPAction:
User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT)
Accept-Encoding: gzip, deflate
Accept: */*
Content-Length: 586
ECID-Context:
<ECID>
Connection: Keep-Alive
Proxy-Client-IP: x.x.x.x
X-Forwarded-For: x.x.x.x
X-WebLogic-KeepAliveSecs: 30
X-WebLogic-Request-ClusterInfo: true
x-weblogic-cluster-hash: NNNNNNNNNN

]", which is more than the configured time (StuckThreadMaxTime) of "600"
seconds. Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:941)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261)
java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594)
oracle.fabric.common.wsdl.SchemaManager.lookupSchema(SchemaManager.java:296)
oracle.fabric.common.wsdl.SchemaManager.lookupXSDElementDeclaration(SchemaManager.java:553)
com.collaxa.cube.xml.xsd.SchemaToXML.generateXMLElement(SchemaToXML.java:369)
...

<May 17, 2011 7:54:11 PM EDT> <Error> <oracle.soa.bpel.engine> <BEA-000000>
<Error occured while handling a post operation
javax.ejb.EJBException: EJB Exception: : java.lang.RuntimeException: An
invocation of EJB BPELDeliveryBean(Application: soa-infra, EJBComponent:
ejb_ob_engine_wls.jar) timed out while waiting to get an instance from the
free pool.
at weblogic.ejb.container.pool.StatelessSessionPool.waitForBean(StatelessSessionPool.java:292)
at weblogic.ejb.container.pool.StatelessSessionPool.getBean(StatelessSessionPool.java:116)
...
<May 17, 2011 7:54:38 PM EDT> <Notice> <Diagnostics> <BEA-320068> <Watch
'StuckThread' with severity 'Notice' on server '<soa server>' has triggered at
May 17, 2011 7:54:38 PM EDT. Notification details:
WatchRuleType: Log
WatchRule: (SEVERITY = 'Error') AND ((MSGID = 'WL-000337') OR (MSGID =
'BEA-000337'))
WatchData: DATE = May 17, 2011 7:54:38 PM EDT SERVER = <soa server> MESSAGE =
[STUCK] ExecuteThread: '147' for queue: 'weblogic.kernel.Default
(self-tuning)' has been busy for "718" seconds working on the request
"weblogic.servlet.internal.ServletRequestImpl@1245cdf2[
POST
/soa-infra/services/default/xxxx/<name>_client?WSDL
HTTP/1.1
Content-Type: text/xml; charset=utf-8
Cache-Control: no-cache
SOAPAction:
User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT)
Accept-Encoding: gzip, deflate
Accept: */*
Content-Length: xxx
ECID-Context:
<ECID>
Connection: Keep-Alive
Proxy-Client-IP: x.x.x.x
X-Forwarded-For: x.x.x.x
X-WebLogic-KeepAliveSecs: 30
X-WebLogic-Request-ClusterInfo: true
x-weblogic-cluster-hash: NNNNNNNNNNNNNNN

]", which is more than the configured time (StuckThreadMaxTime) of "600"
seconds. Stack trace:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:941)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261)
java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594)
oracle.fabric.common.wsdl.SchemaManager.lookupSchema(SchemaManager.java:296)
oracle.fabric.common.wsdl.SchemaManager.lookupXSDElementDeclaration(SchemaManager.java:553)
com.collaxa.cube.xml.xsd.SchemaToXML.generateXMLElement(SchemaToXML.java:369)
com.collaxa.cube.engine.ext.bpel.v2.BPEL2Process.initRootScope(BPEL2Process.java:157)
com.collaxa.cube.engine.CubeEngine.createInstance(CubeEngine.java:1928)

java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xnnnnnnn> (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:941)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261)
at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594)
at oracle.fabric.common.wsdl.SchemaManager.lookupSchema(SchemaManager.java:296)

According to analysis the above lock may be held by:

"[STUCK] ExecuteThread: '4' for queue: 'weblogic.kernel.Default
(self-tuning)'" daemon prio=3 tid=0xnnnnnn nid=0x57 waiting for
monitor entry [0xnnnnnnnnn]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.fabric.common.wsdl.SchemaManager.loadAllXSD(SchemaManager.java:211)
- waiting to lock <0xnnnnnnn> (a
oracle.fabric.common.wsdl.SchemaManager)
at oracle.fabric.common.wsdl.SchemaManager.buildXDKSchema(SchemaManager.java:445)
at oracle.fabric.common.wsdl.SchemaManager.lookupSchema(SchemaManager.java:308)

Which is waiting for lock held by:

"[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default
(self-tuning)'" daemon prio=3 tid=0xnnnnnnnnn nid=0xnn waiting on
condition [0xnnnnnn]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xnnnnnn> (a
java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178)
at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:807)
at oracle.fabric.common.wsdl.SchemaManager.lookupSchema(SchemaManager.java:305)

THIS INDICATES A DEADLOCK

May see many threads trying to lock monitor.

This is shown by following stack traces:

java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xnnnnn> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2116)
at weblogic.ejb.container.pool.StatelessSessionPool.waitForBean(StatelessSessionPool.java:285)
at weblogic.ejb.container.pool.StatelessSessionPool.getBean(StatelessSessionPool.java:116)
at weblogic.ejb.container.manager.StatelessManager.preInvoke(StatelessManager.java:148)
at weblogic.ejb.container.internal.BaseLocalObject.preInvoke(BaseLocalObject.java:241)
at weblogic.ejb.container.internal.BaseLocalObject.preInvoke(BaseLocalObject.java:188)
at weblogic.ejb.container.internal.StatelessLocalObject.__WL_preInvoke(StatelessLocalObject.java:52)
at weblogic.ejb.container.internal.SessionLocalMethodInvoker.invoke(SessionLocalMethodInvoker.java:23)
at com.collaxa.cube.engine.ejb.impl.bpel.BPELDeliveryBean_5k948i_ICubeDeliveryLocalBeanImpl.request(Unknown Source)