這幾天做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的話，那么這個事務就不應該在短短的１０多分鐘內被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，然后它會發起一個ＲＭＩ請求到server_2，server_2完成本地的beforeCompletion后，繼續要求
server_3, server_3完成后要求server_４，如此這般，鏈式完成個server的工作，直到最后一個server（即ｓserver_４） ，server_４發現自己是最后一個，它會負責將PrePrepare OK的Ａck返回給 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在weblogic９中引入，相對于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是怎么實現上述狀態切換超時控制的呢？當從狀態Ａ切換到Ｂ的時候，如果到Ｂ所需要的所有工作都已經完成，那么weblogic事務狀態設定成Ｂ，并重置wakeUpAfterSeconds（從Ｂ到下一狀態的時間限制），這個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)
>
posted on 2009-02-24 10:54
走走停停又三年 閱讀(3986)
評論(2) 編輯 收藏 所屬分類:
Weblogic