In This Section
Overview
AepEngine Statistics are collected and reported in an aggregated fashion – using counters and and histographical collection for latencies. This allows them to printed and and reported in XVM Hearbeats 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 that can be viewed for subsequent analysis.
Per transaction stats are currently classified as an experimental feature. While this feature is a supported feature, it is subject to refinement and change in the future releases.
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.
Enabling Per Transaction Stats
Per transaction stats collection can be enabled with the capturePerTransactionStats configuration property for an application, and configuring a dedicated binary transaction log using the perTransactionStatsLogging configuration element. Per transaction stats collection collects timestamps that are captured when recording message latency stats, ODS store latency stats and transaction latency stats, so those must be enabled as well to be included in per transaction stats. The DDL configuration block below shows a typical set of configuration for collecting all per transaction stats:
Configure Per Transaction Stats Collection
With the above configuration the application will create a processor.txnstats.log in the application's data directory. At the end of each transaction, an AepMonTransactionStatsMessage will be saved to this transaction log file which contains the captured stats for that transaction.
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.
| Field | Description |
|---|---|
| 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 comitted. 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 (EventSourcing) or inbound message log (StateReplication).
| Field | Description |
|---|---|
| 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 (StateReplication) or outbound message log (EventSourcing).
| Field | Description |
|---|---|
| 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 AepEngine send call for the message was entered. |
| AEPSendExitTsMicros | The timestamp, in microseconds, at which the AepEngine send call for the message completed. |
| AEPSendCommitTsMicros | The timestamp, in microseconds, at which the message was commited 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 transactionInSequence numbers associated with each timing. Below is a sample of what the transaction log entries might look like in EventSourcing app with adaptive batching enabled for an app named 'processor' thate receives 3 NewOrderMessages:
processor.log
The recovery log would contain the inbound messages used for recovery
| Entry | transactionId | simpleClassName | transactionInSequenceNumber | transactionOutSequenceNumber |
|---|---|---|---|---|
| 1 | 1 | NewOrderMessage | 1 | 0 |
| 2 | 1 | NewOrderMessage | 2 | 0 |
| 3 | 2 | NewOrderMessage | 1 | 0 |
| 4 | 2 | NewOrderMessage | 2 | 0 |
procesor.out.log
The outbound message log would contain the outbound messages
| Entry | transactionId | simpleClassName | transactionInSequenceNumber | transactionOutSequenceNumber |
|---|---|---|---|---|
| 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 |
procesor.txnstats.log
One entry per transaction, with inbound and outbound timings entry for each message in the transaction:
| Entry | transactionId | simpleClassName | AepMonInboundMessageTimings[] insnos | AepMonOubtoundMessageTimings[] insno/outsnos |
|---|---|---|---|---|
| 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.log
- rdat/processor.in.log
- rdat/processor.out.log
- rdat/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 formated as timestamps to make it easier for tools to calculate the difference in microseconds between timestatmps.
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 StateReplication applications. Additionally the TransactionStatsLogTool does not currently explicitly support checkpoint versioned logs.