Oracle Service Bus –线程阻塞案例研究

本案例研究描述了在AIX 6.1和IBM Java VM 1.6上运行的Oracle Service Bus 11g遇到的线程阻塞问题的完整根本原因分析过程。

本文也是您提高线程转储分析技能的绝佳机会，我强烈建议您学习并正确理解以下分析方法。与过早的中间件（Weblogic）重新启动相比，它还将证明正确收集数据的重要性。

环境规格

Java EE服务器：Oracle Service Bus 11g
操作系统：AIX 6.1
JDK：IBM JRE 1.6.0 @ 64位
RDBMS：Oracle 10g
平台类型：企业服务总线

故障排除工具

Quest Software Foglight for Java（监视和警报）
Java VM线程转储（IBM JRE javacore格式）

问题概述

从我们的Oracle Service Bus Weblogic环境中观察到主要性能下降。 Foglight代理还发送了警报，表明Weblogic线程使用率显着增加。

事实的收集和验证

像往常一样，Java EE问题调查需要收集技术事实和非技术事实，因此我们可以得出其他事实和/或就根本原因进行结论。在采取纠正措施之前，要对以下事实进行核实，以便得出根本原因：

对客户有什么影响？高
受影响平台的最近更改？是的，在中断报告之前，OSB控制台中的一些业务服务的日志记录级别已更改
受影响平台最近的流量增加了吗？没有
自从多久以来观察到此问题？日志记录级别更改后观察到新问题
重新启动Weblogic服务器是否可以解决问题？是

结论1 ：先前在某些OSB商业服务上应用的日志记录级别更改似乎触发了此线程阻塞问题。但是，此时的根本原因仍然未知。

Weblogic线程监视：Java的Foglight

Foglight for Java （来自Quest Software）是一款出色的监视工具，可让您完全监视任何Java EE环境以及完整的警报功能。在我们的生产环境中使用此工具来监视每个Oracle Service Bus受管服务器的中间件（Weblogic）数据，包括线程。您可以在下面看到线程的持续增加以及未决的请求队列。

供您参考，Weblogic运行缓慢的线程被标识为“正在运行的线程”，并且如果运行几分钟（根据您配置的阈值），最终可以提升为“ STUCK”状态。

现在，您下一步应该采取什么行动？ Weblogic重新启动？绝对不是……针对此类问题的第一个“反应”是捕获JVM线程转储。此类数据对于您执行正确的根本原因分析并了解潜在的悬挂状况至关重要。捕获到此类数据后，您就可以继续执行Weblogic服务器恢复操作，例如重新启动完全托管服务器（JVM）。

卡住的线程：线程转储可以进行救援！

此中断场景中的下一个操作步骤是，在尝试恢复受影响的Weblogic实例之前，从IBM JVM快速生成一些线程转储快照。线程转储是使用kill -3 <Java PID>生成的，它确实在Weblogic域的根目录生成了一些javacore文件。

javacore.20120610.122028.15149052.0001.txt

一旦生产环境备份并开始运行，团队将按照以下步骤Swift进行捕获的线程转储文件的分析。

线程转储分析步骤1 –确定线程执行模式

第一步分析是快速遍历所有Weblogic线程，并尝试确定常见的问题模式，例如从远程外部系统等待的线程，处于死锁状态的线程，从其他线程等待以完成其任务的线程等。

该分析确实Swift揭示出许多线程与以下相同的阻塞情况有关。在此示例中，我们可以在TransactionManager Java类（OSB内核代码）中看到处于阻塞状态的Oracle Service Bus线程。

[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))
……………………………

线程转储分析步骤2 –检查被阻塞的线程链

下一步是检查涉及我们确定的模式的受影响和受阻的线程链。正如我们在线程转储分析第4部分中看到的那样，IBM JVM线程转储格式包含一个单独的部分，该部分提供了所有线程阻塞链的完整细分，例如Java对象监视器池锁。

快速分析确实揭示了以下线程元凶。如您所见，Weblogic线程＃16是实际的罪魁祸首，有300多个线程正在等待获取共享库监视器TransactionManager @ 0x0700000001A51610 / 0x0700000001A51628上的锁。

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)
..................

线程转储分析步骤＃3 –线程元凶更深入的分析

一旦确定了罪魁祸首，下一步就是对该线程当前正在执行的计算任务进行更深入的审查。只需返回原始线程转储数据，并从下至上开始分析罪魁祸首线程堆栈跟踪。

正如您在下面看到的那样，针对我们的问题案例的线程堆栈跟踪非常清楚。它确实显示线程＃16当前正在尝试提交在Weblogic / Oracle Service Bus级别进行的更改。问题在于，提交操作正在挂起并且花费了太多时间，导致线程＃16将来自TransactionManager的共享对象监视器锁定保留太长时间，并使其他Oracle Service Bus Weblogic线程“饥饿”。

"[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))

根本原因：连接点

在这一点上，事实和线程转储分析的收集确实使我们能够确定事件链如下：