這幾天做welogic xa debug的時候,反復碰到TransactionTimeoutException。我可是把transaction的timeout設到了 100000秒的,一天多,怎麼可能10幾分鐘就timeout掉啊?而且我還把事務分支的timeout調到了一天,即enable "Set XA Transaction Timeout ", "XA Transaction Timeout"=86400秒。注意:XA Transaction Timeout是Weblogic作為transction manager時,要求對應XA resource的resource manager給transaction branch設定的timeout.如果Set XA Transaction Timeout沒有enable的話,那麼resource manager會使用自己的Timeout去控制transaction branch。
1 public void xaTest()
2 {
3 try{
4 UserTransaction tx = getUserTransaction();
5 System.out.println("tx: " + tx.toString());
6 tx.setTransactionTimeout(100000);
7 tx.begin();
8 Connection conn1 = getConnection("t3://localhost:7011", XA_DS);
9 Connection conn2 = getConnection("t3://localhost:7021", REMOTE_XA_DS);
10 this.executeInsertInPSMT(conn1, null);
11 this.executeAnoInsertInPSMT(conn2, null);
12 conn1.close();
13 conn2.close();
14 tx.commit();
15 }catch(Exception e){
16 e.printStackTrace();
17 }
18 }
異常堆棧如下:
weblogic.transaction.RollbackException: Timed out tx=BEA1-0000DB7D6CD6F87E5FE6 after 100000 seconds
at weblogic.rjvm.ResponseImpl.unmarshalReturn(ResponseImpl.java:215)
at weblogic.rmi.internal.BasicRemoteRef.invoke(BasicRemoteRef.java:224)
at weblogic.transaction.internal.CoordinatorImpl_923_WLStub.commit(Unknown Source)
at weblogic.transaction.internal.TransactionImpl.commit(TransactionImpl.java:324)
at weblogic.transaction.internal.TransactionManagerImpl.commit(TransactionManagerImpl.java:283)
at weblogic.transaction.internal.TransactionManagerImpl.commit(TransactionManagerImpl.java:277)
at com.bea.cs.test.jdbc.DriverTest.xaTest(DriverTest.java:293)
at com.bea.cs.test.jdbc.DriverTest.main(DriverTest.java:49)
Caused by: weblogic.transaction.RollbackException: Timed out tx=BEA1-0000DB7D6CD6F87E5FE6 after 100000 seconds
at weblogic.transaction.internal.TransactionImpl.throwRollbackException(TransactionImpl.java:1809)
at weblogic.transaction.internal.ServerTransactionImpl.internalCommit(ServerTransactionImpl.java:331)
at weblogic.transaction.internal.ServerTransactionImpl.commit(ServerTransactionImpl.java:227)
at weblogic.transaction.internal.CoordinatorImpl.commit(CoordinatorImpl.java:101)
at weblogic.transaction.internal.CoordinatorImpl_WLSkel.invoke(Unknown Source)
at weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:553)
at weblogic.rmi.internal.BasicServerRef$1.run(BasicServerRef.java:443)
at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:147)
at weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:439)
at weblogic.rmi.internal.BasicServerRef.access$300(BasicServerRef.java:61)
at weblogic.rmi.internal.BasicServerRef$BasicExecuteRequest.run(BasicServerRef.java:983)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)
如果只有這幾個timeout的話,那麼這個事務就不應該在短短的10多分鐘內被rollback.調查後發現,除了這幾個上面的兩個 timeout,weblogic內部還有幾個跟事務狀態有關的timeout,不過這幾個timeout都是internal的,最終用戶是無法對其進行配置的。
對於一個能正常結束的transaction,weblogic中,它會經歷如下幾個狀態,New, PrePrepared , Logging(if logging is necessary) ,Prepared, Committed or Rollbacked. 這幾個狀態切換前,weblogic完成工作如下:
New---->PrePrepared: 完成synchronization list的beforeCompletion(), 這個工作是以鏈式方式完成的,加入involve到某個global transaction中的xa resources分別駐留於server_1, server_2, server_3, server_4上,加入 server_1 充當的是coordinator, 其余三個充當的是subcoordinator。那麼server_1首先會完成本地synchronization 的 beforeCompletion,然後它會發起一個RMI請求到server_2,server_2完成本地的beforeCompletion後,繼續要求
server_3, server_3完成後要求server_4,如此這般,鏈式完成個server的工作,直到最後一個server(即sserver_4) ,server_4發現自己是最後一個,它會負責將PrePrepare OK的Ack返回給 coordinator,即server_1。
PrePrepared---->Logging: 這個階段coordinator會以並行的方式要求每個subcoordinator完成prepare的工作,當所以subcoordinator的 prepare Ack都收到後,它會開始做它本地resource的prepare。所以XA resources都Prepare OK後,coordinator開始要求non-xa-resource(最多只有一個,emulate_2PC或LLR)去做commit.non- xa-resource完成commit後,coordinator將判斷是否需要將這個global transaction記入tlog,如果需要,transaction的狀態將被切換到Logging,否則到Prepared。關於 emulate_2PC和LLR的區別,這裡不做過多討論,但值得注意的是,LLR在weblogic9中引入,相對於emulate_2PC,LLR的事務可靠性更高。emulate_2PC以文件方式記錄tlog,而LLR則使用數據庫表方式記錄。如果傳統的emulate_2PC在non-xa- resource提交成功後和global transaction記入tlog前發生系統crash,那麼這個事務就會產生不一致性。non-xa-resource已經提交,而其余xa- resource則處於preprared狀態,最終可能會被會滾掉。而LLR采用數據庫表方式,把non-xa-resource的操作、tlog記入放在一個transaction branch中,則不會發生上述情況。
Logging---->Prepared:將global transaction記入tlog,以備recover.
Prepared---->Committed :工作內容、順序基本同於Prepare,不過有點區別是:這裡要求 subcoordinator完成的是commit, 操作順序上也稍有點區別,首先是non-xa-resource的commit,然後是subcoordinator的commit,最後才是 coordinator的local xa resource commit.
狀態切換過程中,事務超時並不尊從global transaction timeout,而是依照weblogic內部狀態切換超時規定,所謂狀態切換超時是指transaction 從這一狀態切換到下一狀態的時間限制,在這限制時間內,必須完成狀態切換所需要完成的工作。比如,從PrePrepared---->Logging,必須完成所有 xa_resource, non_xa_resource的prepare.這些超時在weblogic內部使用的都是常量,是不可配置的。
PrePrepared---->Logging:60secs
Logging---->Prepared:30secs
Prepared---->Committed :120secs
那麼weblogic是怎麼實現上述狀態切換超時控制的呢?當從狀態A切換到B的時候,如果到B所需要的所有工作都已經完成,那麼 weblogic事務狀態設定成B,並重置wakeUpAfterSeconds(從B到下一狀態的時間限制),這個 wakeUpAfterSeconds對於狀態切換,都是些常量,即多少秒後,這個事務會被觸發超時。比如從 PrePrepared---->Logging,我們完成preprepare的工作後,會切換事務狀態到preprepare,並將狀態切換超時設定到PrePrepared---->Logging的時間限制,如下:
1 private final void setPrePreparedUnsync() {
2 setState(STATE_PRE_PREPARED);
3 ..
4 wakeUpAfterSeconds(Constants.PRE_PREPARED_WAIT_SECONDS);
5 }
也就是說,雖然我們將global transaction timeout設定的很長,但如果某一狀態切換過程耗費時間過長,事務同樣會被超時掉。
加入如下的debug options,可以debug 出詳細信息,
-Dweblogic.debug.DebugJTA2PC=true, -Dweblogic.debug.DebugJTA2PCStackTrace=true
下面是一段debug輸出,注意其中的wakeUpAfterSeconds為120secs
####<Feb 23, 2009 1:05:09 PM CST> <Debug> <JTA2PC> <fjin> <server_1> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <BEA1-02A2E9A37F31> <> <1235365509343> <000000> <java.lang.Exception: DEBUG: Name=JDBC Internal,Xid=BEA1-02A2E9A37F31(19522730),Status=Prepared,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=0,seconds left=3000,activeThread=Thread[[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)',5,Pooled Threads],SCInfo[driver_test_domain+server_1]=(state=pre-prepared),properties=({weblogic.transaction.name=JDBC Internal}),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=server_1+192.168.0.51:7011+driver_test_domain+t3+, XAResources={OracleXADS},NonXAResources={})]) wakeUpAfterSeconds(120)
at weblogic.transaction.internal.TxDebug.debugStack(TxDebug.java:60)
at weblogic.transaction.internal.TransactionImpl.wakeUpAfterSeconds(TransactionImpl.java:1940)
at weblogic.transaction.internal.ServerTransactionImpl.setPreparedUnsync(ServerTransactionImpl.java:3095)
at weblogic.transaction.internal.ServerTransactionImpl.globalPrepare(ServerTransactionImpl.java:2179)
at weblogic.transaction.internal.ServerTransactionImpl.internalCommit(ServerTransactionImpl.java:266)
at weblogic.transaction.internal.ServerTransactionImpl.commit(ServerTransactionImpl.java:227)
at weblogic.transaction.internal.TransactionManagerImpl.commit(TransactionManagerImpl.java:283)
at weblogic.jdbc.common.internal.ConnectionEnv.test(ConnectionEnv.java:684)
at weblogic.jdbc.common.internal.ConnectionEnv.test(ConnectionEnv.java:460)
at weblogic.common.resourcepool.ResourcePoolImpl.checkResource(ResourcePoolImpl.java:1504)
at weblogic.common.resourcepool.ResourcePoolImpl.checkAndReturnResource(ResourcePoolImpl.java:1413)
at weblogic.common.resourcepool.ResourcePoolImpl.checkAndReturnResource(ResourcePoolImpl.java:1401)
at weblogic.common.resourcepool.ResourcePoolImpl.testUnusedResources(ResourcePoolImpl.java:1834)
at weblogic.common.resourcepool.ResourcePoolImpl.access$700(ResourcePoolImpl.java:37)
at weblogic.common.resourcepool.ResourcePoolImpl$ResourcePoolMaintanenceTask.timerExpired(ResourcePoolImpl.java:2002)
at weblogic.timers.internal.TimerImpl.run(TimerImpl.java:265)
at weblogic.work.ServerWorkManagerImpl$WorkAdapterImpl.run(ServerWorkManagerImpl.java:518)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:209)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)
>