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

根本原因：連接點
?
在這一點上，事實和線程轉儲分析的收集確實使我們能夠確定事件鏈如下：