Oracle Service Bus – Stuck Thread Case Study
Join the DZone community and get the full member experience.
Join For Free
- Java EE server: Oracle Service Bus 11g
- OS: AIX 6.1
- JDK: IBM JRE 1.6.0 @64-bit
- RDBMS: Oracle 10g
- Platform type: Enterprise Service Bus
- Quest Software Foglight for Java (monitoring and alerting)
- Java VM Thread Dump (IBM JRE javacore format)
Problem overview
- What is the client impact? HIGH
- Recent change of the affected platform? Yes, logging level changed in OSB console for a few business services prior to outage report
- Any recent traffic increase to the affected platform? No
- Since how long this problem has been observed? New problem observed following logging level changes
- Did a restart of the Weblogic server resolve the problem? Yes
javacore.20120610.122028.15149052.0001.txt
[ACTIVE] ExecuteThread: '292' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x0000000139B76B00, j9thread_t:0x000000013971C9A0, java/lang/Thread:0x07000000F9D80630, state:B, prio=5 (native thread ID:0x2C700D1, native priority:0x5, native policy:UNKNOWN) Java callstack: at com/bea/wli/config/transaction/TransactionManager._beginTransaction(TransactionManager.java:547(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.beginTransaction(TransactionManager.java:409(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedResourceManager.getDerivedValueInfo(DerivedResourceManager.java:339(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedResourceManager.get(DerivedResourceManager.java:386(Compiled Code)) at com/bea/wli/sb/resources/cache/DefaultDerivedTypeDef.getDerivedValue(DefaultDerivedTypeDef.java:106(Compiled Code)) at com/bea/wli/sb/pipeline/RouterRuntimeCache.getRuntime(RouterRuntimeCache.java(Compiled Code)) at com/bea/wli/sb/pipeline/RouterManager.getRouterRuntime(RouterManager.java:640(Compiled Code)) at com/bea/wli/sb/pipeline/RouterContext.getInstance(RouterContext.java:172(Compiled Code)) at com/bea/wli/sb/pipeline/RouterManager.processMessage(RouterManager.java:579(Compiled Code)) at com/bea/wli/sb/transports/TransportManagerImpl.receiveMessage(TransportManagerImpl.java:375(Compiled Code)) at com/bea/wli/sb/transports/local/LocalMessageContext$1.run(LocalMessageContext.java:179(Compiled Code)) at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:363(Compiled Code)) at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:146(Compiled Code)) at weblogic/security/Security.runAs(Security.java:61(Compiled Code)) at com/bea/wli/sb/transports/local/LocalMessageContext.send(LocalMessageContext.java:144(Compiled Code)) at com/bea/wli/sb/transports/local/LocalTransportProvider.sendMessageAsync(LocalTransportProvider.java:322(Compiled Code)) at sun/reflect/GeneratedMethodAccessor980.invoke(Bytecode PC:58(Compiled Code)) at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37(Compiled Code)) at java/lang/reflect/Method.invoke(Method.java:589(Compiled Code)) at com/bea/wli/sb/transports/Util$1.invoke(Util.java:83(Compiled Code)) at $Proxy111.sendMessageAsync(Bytecode PC:26(Compiled Code)) ……………………………

2LKMONINUSE sys_mon_t:0x000000012CCE2688 infl_mon_t: 0x000000012CCE26C8: 3LKMONOBJECT com/bea/wli/config/transaction/TransactionManager@0x0700000001A51610/0x0700000001A51628: Flat locked by "[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CA3C800), entry count 1 3LKWAITERQ Waiting to enter: 3LKWAITER "[STUCK] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011C785C00) 3LKWAITER "[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011CA93200) 3LKWAITER "[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011B3F2B00) 3LKWAITER "[STUCK] ExecuteThread: '3' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000011619B300) 3LKWAITER "[STUCK] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012CBE8000) 3LKWAITER "[STUCK] ExecuteThread: '21' for queue: 'weblogic.kernel.Default (self-tuning)'" (0x000000012BE91200) ..................
"[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" J9VMThread:0x000000012CA3C800, j9thread_t:0x000000012C9F0F40, java/lang/Thread:0x0700000026FCE120, state:P, prio=5 (native thread ID:0x35B0097, native priority:0x5, native policy:UNKNOWN) Java callstack: at sun/misc/Unsafe.park(Native Method) at java/util/concurrent/locks/LockSupport.park(LockSupport.java:184(Compiled Code)) at java/util/concurrent/locks/AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:822) at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:853(Compiled Code)) at java/util/concurrent/locks/AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1189(Compiled Code)) at java/util/concurrent/locks/ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:911(Compiled Code)) at com/bea/wli/config/derivedcache/DerivedCache$Purger.changesCommitted(DerivedCache.java:80) at com/bea/wli/config/impl/ResourceListenerNotifier.afterEnd(ResourceListenerNotifier.java:120) at com/bea/wli/config/transaction/TransactionListenerWrapper.afterEnd(TransactionListenerWrapper.java:90) at com/bea/wli/config/transaction/TransactionManager.notifyAfterEnd(TransactionManager.java:1154(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.commit(TransactionManager.java:1519(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager._endTransaction(TransactionManager.java:842(Compiled Code)) at com/bea/wli/config/transaction/TransactionManager.endTransaction(TransactionManager.java:783(Compiled Code)) at com/bea/wli/config/deployment/server/ServerDeploymentReceiver$2.run(ServerDeploymentReceiver.java:275) at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:321(Compiled Code)) at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:120(Compiled Code)) at com/bea/wli/config/deployment/server/ServerDeploymentReceiver.commit(ServerDeploymentReceiver.java:260) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer.doCommitCallback(DeploymentReceiverCallbackDeliverer.java:195) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer.access$100(DeploymentReceiverCallbackDeliverer.java:13) at weblogic/deploy/service/internal/targetserver/DeploymentReceiverCallbackDeliverer$2.run(DeploymentReceiverCallbackDeliverer.java:68) at weblogic/work/SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:528(Compiled Code)) at weblogic/work/ExecuteThread.execute(ExecuteThread.java:203(Compiled Code)) at weblogic/work/ExecuteThread.run(ExecuteThread.java:171(Compiled Code))
- Logging level change applied by the production Oracle Service Bus administrator
- Weblogic deployment thread #16 was unable to commit the change properly
- Weblogic runtime threads executing client requests quickly started to queue up and wait for a lock on the shared object monitor (TransactionManager)
- The Weblogic instances ran out of threads, generating alerts and forcing the production support team to shut down and restart the affected JVM processes
Published at DZone with permission of Pierre - Hugues Charbonneau, DZone MVB. See the original article here.
Opinions expressed by DZone contributors are their own.
Comments