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)

Last updated on NOVEMBER 03, 2016

Applies to:

Oracle SOA Platform - Version 11.1.1.4.0 and later
Information in this document applies to any platform.
***Checked for relevance on 10-Dec-2012***

Symptoms

A BPEL Composite 11.1.1.4.0 is generating stuck threads when it is executed under load.

Errors that may be observed in the SOA managed server logfiles at $MIDDLEWARE_HOME/user_projects/domains/<domain name>/<soa server name>/logs:

<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/EscapeV1x1/escapeservicediscovery_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:
1.0001aOMCDXiAtH2_vpd9iX0006hW000Aul;kXjE9ZDLIPHCoFBSjHPBdUQPmHRBnLQSqPRO_JVB^LQPXLSRoV9HnJPOkLQLl8TCj5RSZHOS_JTPmMTQZLOPdJVOjMTPmPVNZSPQ_UOT
Connection: Keep-Alive
Proxy-Client-IP: 10.64.180.10
X-Forwarded-For: 10.64.180.10
X-WebLogic-KeepAliveSecs: 30
X-WebLogic-Request-ClusterInfo: true
x-weblogic-cluster-hash: NROmludGRK3PfX1Eevh/3mEvSH0

]", 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 'wls_soa2' 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 = wls_soa2 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/EscapeV1x1/escapeservicediscovery_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:
1.0001aOICjP^AtH2_vpd9iX0006hW000Au4;kXjE9ZDLIPHCoFBSjHPBdUQPmHRBnLQSqPRO_JVB^LQPXLSRoV9HnJPOkLQLl8TCj5RSZHOS_JTPmMTQZLOPdJVOjMTPmPVNZSPQ_UOT
Connection: Keep-Alive
Proxy-Client-IP: 10.64.180.10
X-Forwarded-For: 10.64.180.10
X-WebLogic-KeepAliveSecs: 30
X-WebLogic-Request-ClusterInfo: true
x-weblogic-cluster-hash: NROmludGRK3PfX1Eevh/3mEvSH0

]", 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)


Taking and analysis of thread dumps during this condition reveal:

java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xffffffff27c24908> (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=0x0000000105387000 nid=0x57 waiting for
monitor entry [0xfffffffee2ef2000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.fabric.common.wsdl.SchemaManager.loadAllXSD(SchemaManager.java:211)
- waiting to lock <0xffffffff27c24898> (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=0x000000010a072000 nid=0x56 waiting on
condition [0xfffffffee30e8000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0xffffffff27c24908> (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 <0xffffffff1eb41960> (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)

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms