Using TransactionSummary Trace in Websphere Application Server

Answer

TransactionSummary trace is intended to be used by both customers and IBM Support to help understand how a transaction progresses. It can be used to determine the following:

1. The order in which resources enlist, prepare and commit, including last participants.
2. The number and type of resources enlisted in a transaction.
3. What component (application server or application itself) starts, commits or rolls back a transaction.
4. The performance of XA calls on particular resources.

TransactionSummary trace can be gathered by enabling trace with the "TransactionSummary=all" trace string. It can be gathered together with regular transaction trace with "Transaction*=all" if required but is most useful for customers on its own. For instructions on enabling trace see the following article in the information center:

http://www14.software.ibm.com/webapp/wsbroker/redirect?version=phil&product=was-nd-mp&topic=ttrb_entrrs

Example output of TransactionSummary trace follows. It is taken from a Message Driven Bean that receives a message in a global transaction and then sends a message.

Note: Bold text is actually TransactionSummary trace output which distinguishes it from text in this technote. Text in italics highlights sections of the trace referred to in the description.

[09/08/13 17:13:00:659 BST] 00000068 TRANSUMMARY 3 Transaction created.
com.ibm.ws.tx.jta.TransactionImpl@f8ce02a2#tid=257821236
{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(40),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe600000001)}
at com.ibm.tx.jta.impl.TransactionImpl.traceCreate(TransactionImpl.java:3873)
at com.ibm.ws.tx.jta.TransactionImpl.<init>(TransactionImpl.java:384)
at com.ibm.ws.tx.jta.TranManagerImpl.createNewTransaction(TranManagerImpl.java:186)
at com.ibm.ws.tx.jta.TranManagerImpl.begin(TranManagerImpl.java:377)
at com.ibm.tx.jta.impl.TranManagerSet.begin(TranManagerSet.java:169)
at com.ibm.ejs.csi.TranStrategy.beginGlobalTx(TranStrategy.java:687)
at com.ibm.ejs.csi.Required.preInvoke(Required.java:75)
at com.ibm.ejs.csi.TransactionControlImpl.preInvoke(TransactionControlImpl.java:299)
at com.ibm.ejs.container.EJSContainer.preInvokeActivate(EJSContainer.java:3665)
at com.ibm.ejs.container.EJSContainer.EjbPreInvoke(EJSContainer.java:3042)
at com.ibm.ejs.container.MDBWrapper.onMessage(MDBWrapper.java:89)
at com.ibm.ejs.container.MDBWrapper.onMessage(MDBWrapper.java:132)
at com.ibm.ejs.jms.listener.ServerSession.run(ServerSession.java:581)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1862)

This entry shows thread 00000068 is starting a transaction. TransactionSummary can be separated from other trace using the TRANSUMMARY entry name. In Liberty profile TRANSUMMARY is seen as WASTr. The above shows the 'tid' of the transaction as well as the full 'xid'. The stack trace for this thread is seen and can be used to determine what has started the transaction. In this case we can see that the transaction was started by the EJB container. If a UserTransaction starts the transaction you would expect to see application stack frames here. The stack trace is also shown if the transaction is marked rollbackOnly to help identify the caller and hence the reason.


[09/08/13 17:13:00:660 BST] 00000068 TRANSUMMARY 3 JTA Resource created:
com.ibm.ws.tx.jta.JTAXAResourceImpl@e4b8a7a5#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000001)}
XAResource: JMS$testCF$JMSManagedConnection@0

This entry shows the thread creating a JTA Resource. Points to note are the hashcode of the JTAXAResourceImpl object (@e4b8a7a5) and a basic string representation of the resource (JMS$testCF$JMSManagedConnection@0). In this case we can see it is a JMS connection factory called testCF. This string will vary depending on the resource but should be enough to indicate the type of resource. The hashcode will be needed to identify this resource later in the trace as this is the only time the string representation is seen. Also note the xid. This xid is the same as the xid seen when the transaction started, but has a branch suffix as well (0000000000000000000000000001).

[09/08/13 17:13:00:660 BST] 00000068 TRANSUMMARY 3 xa_start
com.ibm.ws.tx.jta.JTAXAResourceImpl@e4b8a7a5#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000001)}
[09/08/13 17:13:00:697 BST] 00000068 TRANSUMMARY 3 xa_start result:
XA_OK

The above entries shows the resource created earlier being started.

[09/08/13 17:13:01:023 BST] 00000068 TRANSUMMARY 3 JTA Resource created:
com.ibm.ws.tx.jta.JTAXAResourceImpl@c588b06c#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000002)}
XAResource: JMS$testCF$JMSManagedConnection@0
[09/08/13 17:13:01:023 BST] 00000068 TRANSUMMARY 3 xa_start
com.ibm.ws.tx.jta.JTAXAResourceImpl@c588b06c#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000002)}
[09/08/13 17:13:01:065 BST] 00000068 TRANSUMMARY 3 xa_start result:
XA_OK


The above entries show another JTA resource being created and started. It is another JMS resource from the same connection factory. Note its hashcode and also its branch (0000000000000000000000000002 instead of 0000000000000000000000000001).

[09/08/13 17:13:01:148 BST] 00000068 TRANSUMMARY 3 xa_end
com.ibm.ws.tx.jta.JTAXAResourceImpl@c588b06c#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000002)}
flags = 4000000=TMSUCCESS
[09/08/13 17:13:01:183 BST] 00000068 TRANSUMMARY 3 xa_end result:
XA_OK
[09/08/13 17:13:01:183 BST] 00000068 TRANSUMMARY 3 xa_end
com.ibm.ws.tx.jta.JTAXAResourceImpl@e4b8a7a5#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000001)}
flags = 4000000=TMSUCCESS
[09/08/13 17:13:01:216 BST] 00000068 TRANSUMMARY 3 xa_end result:
XA_OK


The above entries show the resources created earlier being ended. Note the order is the reverse of the order in which they were created (enlisted).

[09/08/13 17:13:01:216 BST] 00000068 TRANSUMMARY 3 xa_prepare
com.ibm.ws.tx.jta.JTAXAResourceImpl@c588b06c#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000002)}
[09/08/13 17:13:01:272 BST] 00000068 TRANSUMMARY 3 xa_prepare result XA_OK
[09/08/13 17:13:01:272 BST] 00000068 TRANSUMMARY 3 xa_prepare
com.ibm.ws.tx.jta.JTAXAResourceImpl@e4b8a7a5#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000001)}
09/08/13 17:13:01:319 BST] 00000068 TRANSUMMARY 3 xa_prepare result XA_OK

The above entries show the resources being prepared, again in reverse order.

[09/08/13 17:13:01:319 BST] 00000068 TRANSUMMARY 3 xa_commit
com.ibm.ws.tx.jta.JTAXAResourceImpl@e4b8a7a5#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000001)}
[09/08/13 17:13:01:353 BST] 00000068 TRANSUMMARY 3 xa_commit result: XA_OK
[09/08/13 17:13:01:353 BST] 00000068 TRANSUMMARY 3 xa_commit
com.ibm.ws.tx.jta.JTAXAResourceImpl@c588b06c#{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(54),
data(0000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe60000014063da3973000000010f5e0a3456030d47b4232e8cc800677807c6f8bd9cca1fe6000000010000000000000000000000000002)}
[09/08/13 17:13:01:395 BST] 00000068 TRANSUMMARY 3 xa_commit result: XA_OK

The above entries show the resources being committed, this time in the order in which they were enlisted. Some resources might have special handling to ensure they commit last, for example Service Integration Bus.

An example of a thread marking the transaction rollbackOnly is:

[09/08/13 17:05:27:739 BST] 00000060 TRANSUMMARY 3 Transaction setRollbackOnly.
com.ibm.ws.tx.jta.TransactionImpl@b7206512#tid=256714804
{XidImpl: formatId(57415344), gtrid_length(36), bqual_length(40),
data(0000014063d34a0c000000010f4d2834dd91668516b52fca5490b5e638ff6de56dcd39aa0000014063d34a0c000000010f4d2834dd91668516b52fca5490b5e638ff6de56dcd39aa00000001)}
at com.ibm.ws.tx.jta.TransactionImpl.setRBO(TransactionImpl.java:1001)
at com.ibm.ws.tx.jta.TransactionImpl.setRollbackOnly(TransactionImpl.java:2028)
at com.ibm.ws.tx.jta.TransactionImpl.setRollbackOnly(TransactionImpl.java:2000)
at com.ibm.tx.jta.impl.TranManagerImpl.setRollbackOnly(TranManagerImpl.java:356)
at com.ibm.tx.jta.impl.TranManagerSet.setRollbackOnly(TranManagerSet.java:221)
at com.ibm.ejs.csi.TransactionControlImpl.setRollbackOnly(TransactionControlImpl.java:725)
at com.ibm.ejs.container.ContainerTx.setRollbackOnly(ContainerTx.java:1707)
at com.ibm.ejs.container.BeanO.setRollbackOnly(BeanO.java:1235)
at com.ibm.ejs.container.MessageDrivenBeanO.setRollbackOnly(MessageDrivenBeanO.java:942)
at com.ibm.ejs.jms.listener.ServerSession.connectionConsumerOnMessage(ServerSession.java:1110)
at com.ibm.ejs.jms.listener.ServerSession.onMessage(ServerSession.java:760)
at com.ibm.ejs.jms.listener.ServerSession.dispatch(ServerSession.java:726)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:60)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:37)
at java.lang.reflect.Method.invoke(Method.java:611)
at com.ibm.ejs.jms.listener.ServerSessionDispatcher.dispatch(ServerSessionDispatcher.java:47)
at com.ibm.ejs.container.MDBWrapper.onMessage(MDBWrapper.java:100)
at com.ibm.ejs.container.MDBWrapper.onMessage(MDBWrapper.java:132)
at com.ibm.ejs.jms.listener.ServerSession.run(ServerSession.java:581)
at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1862)

In this case we can see that the Listener Port is using the MessageDrivenBeanContext to mark the transaction roll back only due to a RuntimeException. If an application had marked the transaction rollbackOnly you would expect to find application stack frames here.

The time gap between trace entries can be used as a rough indication of the performance of certain XA operations for a given resource.

TransactionSummary trace is added as a tool in 8.0.0.8 and 8.5.5.2.