MSDTC Does Not Correctly Log All XA Transaction Details

 

If you’re having to work with the Microsoft Distributed Transaction Coordinator transaction logs, you must already be having a very fun day. To add to your joy, I’ve recently learned that MSDTC does not correctly log XA transaction details within the Transaction Logs. Let me give you some details that I’ve picked up.

Two Scenarios for xa_commit

With TMONEPHASE

The TMONEPHASE flag notifies us the caller is using one-phase commit optimizations.  If you want to dump out the transaction logs here you will only find the following entry for a commit (formatted to read more clearly):

pid=5888 tid=5024 time=01/23/2015-12:14:30.098 seq=758 eventid=RM_ENLISTED_IN_TRANSACTION

Compare this to the Transaction::Commit call which utilize one-phase commit optimizations (I’ve bolded what is missing):

pid=5524           tid=5404           time=01/23/2015-12:11:48.822       seq=71             TRANSACTION_BEGUN                   
pid=5524           tid=5404           time=01/23/2015-12:11:48.822       seq=72             RM_ENLISTED_IN_TRANSACTION          
pid=5524           tid=5404           time=01/23/2015-12:11:48.822       seq=73             RECEIVED_COMMIT_REQUEST_FROM_BEGINNER
pid=5524           tid=5404           time=01/23/2015-12:11:48.822       seq=74             TRANSACTION_COMMITTED               

Without TMONEPHASE

The situation is better when we do use the one-phase optimizations:

pid=5888           tid=5808           time=01/23/2015-12:14:46.586       seq=3473           eventid=RM_ENLISTED_IN_TRANSACTION
pid=5888           tid=5808           time=01/23/2015-12:14:46.586       seq=3474           eventid=RM_ENLISTED_IN_TRANSACTION
pid=5888           tid=5808           time=01/23/2015-12:14:46.586       seq=3475           eventid=RM_ISSUED_PREPARE         
pid=5888           tid=5808           time=01/23/2015-12:14:46.586       seq=3476           eventid=RM_ISSUED_PREPARE         
pid=5888           tid=5808           time=01/23/2015-12:14:46.601       seq=3477           eventid=RM_VOTED_COMMIT           
pid=5888           tid=5808           time=01/23/2015-12:14:46.601       seq=3478           eventid=RM_VOTED_COMMIT           
pid=5888           tid=5808           time=01/23/2015-12:14:46.617       seq=3479           eventid=RM_ISSUED_COMMIT          
pid=5888           tid=5808           time=01/23/2015-12:14:46.617       seq=3480           eventid=RM_ISSUED_COMMIT          
pid=5888           tid=5808           time=01/23/2015-12:14:46.617       seq=3481           eventid=RM_ACKNOWLEDGED_COMMIT    
pid=5888           tid=5808           time=01/23/2015-12:14:46.617       seq=3482           eventid=RM_ACKNOWLEDGED_COMMIT    

Compare this to the Transaction::Commit call which does not utilize one-phase commit optimizations (I’ve bolded what is missing)::

pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12141          TRANSACTION_BEGUN                    
pid=5524           tid=5980           time=01/23/2015-12:12:03.348       seq=12142          RM_ENLISTED_IN_TRANSACTION           
pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12143          RM_ENLISTED_IN_TRANSACTION           
pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12144          RECEIVED_COMMIT_REQUEST_FROM_BEGINNER
pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12145          RM_ISSUED_PREPARE                    
pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12146          RM_ISSUED_PREPARE                    
pid=5524           tid=5380           time=01/23/2015-12:12:03.348       seq=12147          RM_VOTED_COMMIT                      
pid=5524           tid=5980           time=01/23/2015-12:12:03.348       seq=12148          RM_VOTED_COMMIT                      
pid=5524           tid=5980           time=01/23/2015-12:12:03.364       seq=12149          TRANSACTION_COMMITTED                
pid=5524           tid=5980           time=01/23/2015-12:12:03.364       seq=12150          RM_ISSUED_COMMIT                     
pid=5524           tid=5980           time=01/23/2015-12:12:03.364       seq=12151          RM_ISSUED_COMMIT                     
pid=5524           tid=5980           time=01/23/2015-12:12:03.364       seq=12152          RM_ACKNOWLEDGED_COMMIT               
pid=5524           tid=5380           time=01/23/2015-12:12:03.364       seq=12153          RM_ACKNOWLEDGED_COMMIT               

I’ll be following this entry up later with some information about XA performance compared to OleTx transactions.