Per Transaction Stats
AEP Engine Statistics are collected and reported in an aggregated fashion using counters and histographical collection for latencies. This allows them to be printed and reported in XVM Heartbeats in a compact fashion without adding excessive overhead. When combined with message type stats and a reasonably frequent collection interval, these aggregate stats are usually enough to provide a clear picture of what is causing performance bottlenecks in an application.
When aggregated stats don't provide enough detail, per transaction stats provide a means of collecting and recording statistics for each transaction and message processed therein at the cost of greater overhead. The sections below discuss how to enable per transaction stats collection and how they can be viewed for subsequent analysis.
Experimental Feature: Per transaction stats are currently classified as an experimental feature. While this feature is supported, it is subject to refinement and change in future releases.
Performance Impact: Users are advised to carefully test the performance impact of enabling per transaction stats particularly when operating under load, as collection and reporting of these stats can be quite costly in terms of CPU usage, disk write bandwidth, and disk space usage.
Configuring Per Transaction Stats
Per transaction stats collection can be enabled in your application DDL. For complete configuration details, see:
When enabled, the application will create a <appname>.txnstats.log in the application's data directory. At the end of each transaction, an AepMonTransactionStatsMessage is saved to this transaction log file containing the captured stats for that transaction.
This page focuses on understanding and working with the per-transaction stats logs.
Working with Per Transaction Stats logs
Per transaction stats are logged to an *<appname>.*txnstats.log which will contain AepMonTransactionStatsMessages containing the stats for each message.
AepMonTransactionStatsMessage
The AepMonTransactionStatsMessages has fields for general transaction stats and a listing of stats associated with each inbound and outbound message for the transaction.
transactionId
The transactionId to which the stats correspond
timestamp
The timestamp at which the transaction stats were saved to disk (in milliseconds)
transactionStartTsMicros
Captures the time, in microseconds, at which the transaction was started – the first event or message received for the transaction
commitStartTsMicros
Captures the time, in microseconds, at which transaction commit starts
storeCommitStartTsMicros
Captures the time, in microseconds, at which store commit starts. If the engine is not configured with a store this timestamp may be omitted or set to 0.
storeCommitStartedTsMicros
Captures the time, in microseconds at which the portion of store commit done by the application's business logic thread completes. If the engine is not configured with a store this timestamp may be omitted or set to 0.
storeCommitCompleteTsMicros
Captures the time, in microseconds, that store commit completes (e.g. ack from backup instances, or flush to disk). If the engine is not configured with a store this timestamp may be omitted or set to 0.
sendCommitStartTsMicros
Captures the time, in microseconds, at which commit (send) of outbound messages starts. If the transaction does not contain outbound messages this may be omitted or set to 0.
sendCommitStartedTsMicros
Captures the time, in microseconds, at which outbound sends are committed. Message send commit still continues in the background. If the transaction does not contain outbound messages this may be omitted or set to 0.
sendCommitCompleteTsMicros
Captures the time, in microseconds, at which all sends have been written to their buses and acknowledged (if Guaranteed). If the transaction does not contain outbound messages this may be omitted or set to 0.
commitCompleteTsMicros
Captures the time, in microseconds, at which the transaction is considered complete (both store and send commit completed)
inboundMessageTimings[]
Lists timings associated with inbound messages in the transaction
outboundMessageTimings[]
Lists timings associated with outbound messages in the transaction
AepMonInboundMessageTimings
AepMonInboundMessageTimings contain stats associated with a particular inbound message in an AEP transaction. When the application is configured for adaptive batching, multiple inbound messages can be processed in a single transaction. Each inbound message is assigned an inbound sequence number which can be used to correlate between timings captured here and an inbound messages stored either in the application's recovery transaction log (Event Sourcing) or inbound message log (State Replication).
transactionInSequenceNumber
Indicates the inbound message sequence number within a transaction
SMACreateTsMicros
The timestamp, in microseconds, at which the message was created (or reincarnated from a pool)
SMAPostWireTsMicros
The timestamp, in microseconds, just after a message was received by the message bus
SMAPreDeserializeTsMicros
The timestamp, in microseconds, just before a message was deserialized/wrapped in a message view
SMAPostDeserializeTsMicros
The timestamp, in microseconds, just after a message was deserialized/wrapped in a message view
AEPInputQueueOfferTsMicros
The timestamp, in microseconds, at which the message was offered to the application's input queue
AEPInputQueuePollTsMicros
The timestamp, in microseconds, at which the message was taken off the application's input queue
AEPPreProcessingTsMicros
The timestamp, in microseconds, just before the application's business logic thread dispatches the message for application processing
AEPPostProcessingTsMicros
The timestamp, in microseconds, just after the application's business logic thread finishes message processing
AepMonOutboundMessageTimings
AepMonOutboundMessageTimings contain stats associated with a particular outbound message in an AEP transaction. Each outbound message is assigned an outbound sequence number which records the sequence in which it was sent by the application. When the application is configured for adaptive batching, multiple inbound messages can be processed in a single transaction and processing of each inbound message can result in outbound sends. Each outbound message is therefore also assigned an inbound sequence number which can be used to correlate between timings captured here and the inbound message that produced it. The inbound and outbound message sequence numbers here can be used to correlate the timings with the outbound messages stored either in the application's recovery transaction log (State Replication) or outbound message log (Event Sourcing).
transactionOutSequenceNumber
The outbound sequence number of the message with respect to other outbound messages in the transaction
transactionInSequenceNumber
The inbound sequence number of the message that triggered the send
SMACreateTsMicros
The timestamp, in microseconds, at which the message was created (or reincarnated from a pool)
AEPSendEnterTsMicros
The timestamp, in microseconds, at which the AEP engine send call for the message was entered
AEPSendExitTsMicros
The timestamp, in microseconds, at which the AEP engine send call for the message completed
AEPSendCommitTsMicros
The timestamp, in microseconds, at which the message was committed during the transaction commit
SMASendStartTsMicros
The time at which the sending thread begins sending the message over the message bus
SMAPreSerializeTsMicros
The timestamp, in microseconds, just before the message was serialized for send
SMAPostSerializeTsMicros
The timestamp, in microseconds, just after the message was serialized for send
SMAPreWireTsMicros
The timestamp, in microseconds, just before the serialized message was written to the bus
SMAPostWireTsMicros
The timestamp, in microseconds, just after the serialized message was written to the bus
SMASendEndTsMicros
The time after which send is completed for the message (excluding asynchronous acknowledgement)
Correlating Timings to Logged Messages
The AepMonInbound MessageTimings and AepMonOutboundMessageTimings above described the transactionOutSequenceNumber and transactionInSequenceNumber associated with each timing. Below is a sample of what the transaction log entries might look like in Event Sourcing app with adaptive batching enabled for an app named 'processor' that receives 3 NewOrderMessages:
processor.log
The recovery log would contain the inbound messages used for recovery:
1
1
NewOrderMessage
1
0
2
1
NewOrderMessage
2
0
3
2
NewOrderMessage
1
0
4
2
NewOrderMessage
2
0
processor.out.log
The outbound message log would contain the outbound messages:
1
1
NewOrderEventMessage
1
1
2
1
NewOrderAckMessage
1
2
3
1
NewOrderEventMessage
2
3
4
1
NewOrderAckMessage
2
4
5
2
NewOrderEventMessage
1
1
6
2
NewOrderAckMessage
1
2
7
2
NewOrderEventMessage
2
3
8
2
NewOrderAckMessage
2
4
processor.txnstats.log
One entry per transaction, with inbound and outbound timings entry for each message in the transaction:
1
1
AepMonTransactionStatsMessage
1 and 2
1/1, 1/2, 2/3, 2/4
2
2
AepMonTransactionStatsMessage
1 and 2
1/1, 1/2, 2/3, 2/4
Archiving TxnStats logs
To include txnstats logs with an application's recovery and messages logs, the transaction log tool's archive command accepts a '-s' to indicate that it should be included.
The TransactionStatsLogTool
TxnStats logs can be viewed like any other transaction log using the Transaction Log Tool. However because Transaction Log Tool doesn't support the ability to perform joins across logs, Talon includes a TransactionStatsLogTool which can be used to join the results of a transaction log query with the stats recorded in txnstats log and output the joined results in a comma separated values file.
The TransactionStatsLogTool expects all transaction logs that are to be queried to be located in the same folder and accepts 3 arguments:
recoveryLogPath: The main recovery transaction log path, corresponding ".in.log" and ".out.log" and the "txnstats.log" are opened if they existing in the same directory
query: The transaction log query that selects entries from the logs
outputFileName: The name of the output file to which to write the results
The above invocation would thus look for and open the following transaction logs:
rdat/processor.logrdat/processor.in.logrdat/processor.out.logrdat/processor.txnstats.log
Once launched the tool indexes the txnstats log by transactionId, executes the query (in this case looking for transactions between 10000 and 10010), and dumps out each result from the query. While dumping out those results it will look for matching inbound and outbound messages and append the stats that they have recorded to the output as additional columns.
Sample Output
Each XXXTsMicros timestamp reported in the output reflects the number of microseconds since the epoch. They are not formatted as timestamps to make it easier for tools to calculate the difference in microseconds between timestamps.
Known Limitations
Outbound Message Timestamps When using BestEffort delivery and buses that do sends in a detached mode, it is possible for a message bus to report send commit completion prior to some outbound timestamps being captured.
Epoch Offset Timestamps When epoch offset timestamps are disabled the timestamps captured in the txnstats log will also not be epoch offset with the exception of some timestamps such as preProcessingTsMicros are recorded as epoch offset regardless of this setting. Consequently, it is not recommended that epoch offset timestamps be disabled.
TxnStats Log Size The size of the txnstats log is not currently reported in XVM heartbeats, so users should take extra care that there is sufficient disk space for the log file.
State Replication and Log Compaction There is not currently support for compaction of txnstats logs when doing recovery log compaction for State Replication applications. Additionally the TransactionStatsLogTool does not currently explicitly support checkpoint versioned logs.
Related Topics
Configuring Monitoring - Configure per-transaction statistics
AEP Engine Statistics - Aggregate engine statistics
XVM Stats and Heartbeats - Server heartbeat statistics
Transaction Log Tool - Transaction log browsing and querying
Transactions - Transaction concepts
Next Steps
Understand the performance impact of per-transaction stats
Enable global latency stats collection
Configure per-transaction stats logging in DDL
Test performance under load in non-production environment
Use TransactionStatsLogTool to analyze collected stats
Disable after collecting necessary data
Last updated