这几天做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
走走停停又三年 阅读(3940)
评论(2) 编辑 收藏 所属分类:
Weblogic