环境规格

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

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

• 生产Oracle Service Bus管理员应用的日志记录级别更改
• Weblogic部署线程＃16无法正确提交更改
• 快速执行客户端请求的Weblogic运行时线程开始排队并等待共享对象监视器（TransactionManager）上的锁定
• Weblogic实例的线程不足，生成警报并迫使生产支持团队关闭并重新启动受影响的JVM进程

我们的团队计划不久后开放一个Oracle SR，以共享此OSB部署行为以及客户端请求（线程）和OSB日志记录层之间的硬依赖性。 在此期间，除非另行通知，否则不会在维护时段内尝试更改OSB日志记录级别。

结论
 
我希望本文能帮助您理解和理解强大的线程转储分析功能，以查明线程阻塞问题的根本原因，以及任何Java EE生产支持团队捕获此类重要数据以防止将来再次发生的重要性。 请不要犹豫，发表任何评论或问题。

参考： Oracle服务总线–我们JCG合作伙伴 Pierre-Hugues Charbonneau的“ 阻塞线程”案例研究 ，位于Java EE支持模式和Java教程博客。