...
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. Per Transaction Stats provide a means of collecting and recording statistics for each transaction and message processed which provides the most granular view into the system. The sections below discuss how to enable per transaction stats, and how to to dump them for analysis.
| Note |
|---|
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 it 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
...
| Info | ||
|---|---|---|
| ||
Note that it is not advisable to disable epoch offset timestamps when using per transaction stats. |
Listing of Per Transaction Stats
...
Working with TxnStats log
Per transaction stats are logged to an <appname>.txnstats.log which will contain AepMonTransactionStatsMessages which 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.
AepMonTransactionStats
| 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 st |
| 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 ommitted 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 ommitted or set to 0. |
| sendCommitCompleteTsMicros | Captures the time, in microseconds, at which all sends have been written to their buses and acknowledged (if Guarantteed). If the transaction does not contain outbound messages this may be ommitted 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 assocated with inbound messages in the transaction. |
| outboundMessageTimings[] | Lists timings assocated 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 |
| 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). |
...
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
Talon includes a TransactionStatsLogTool which can be used to generate a comma separated values report of the stats recorded above joined with a user supplied query based on the messages from recovery transaction log, inbound and outbound message logs.
...
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.
| Code Block | ||||
|---|---|---|---|---|
| ||||
Entry.simpleClassName,transactionId,Entry.timestamp,storeCommitStartTsMicros,storeCommitCompleteTsMicros,sendCommitStartedTsMicros,commitCompleteTsMicros,sendCommitStartTsMicros,storeCommitStartedTsMicros,sendCommitCompleteTsMicros,commitStartTsMicros,transactionStartTsMicros,SMAPreDeserializeTsMicros,transactionInSequenceNumber,AEPInputQueueOfferTsMicros,SMAPostDeserializeTsMicros,AEPPreProcessingTsMicros,SMACreateTsMicros,AEPPostProcessingTsMicros,AEPInputQueuePollTsMicros,SMAPostWireTsMicros,SMAPreWireTsMicros,transactionInSequenceNumber,SMASendEndTsMicros,SMAPreSerializeTsMicros,AEPSendExitTsMicros,AEPSendCommitTsMicros,AEPSendEnterTsMicros,SMACreateTsMicros,SMAPostWireTsMicros,SMASendStartTsMicros,SMAPostSerializeTsMicros,transactionOutSequenceNumber "MyInboundMesage",10000,"20170816-02:06:01.478",1502849161478105,1502849161478172,1502849161478173,1502849161478316,1502849161478172,1502849161478125,1502849161478309,1502849161478170,1502849161478102,1502849161477825,1,1502849161477833,1502849161477833,1502849161478104,1502849161477832,1502849161478170,1502849161478102,1502849161477825,,,,,,,,,,,, "MyInboundMesage",10001,"20170816-02:06:01.478",1502849161478177,1502849161478251,1502849161478252,1502849161478413,1502849161478251,1502849161478204,1502849161478407,1502849161478250,1502849161478173,1502849161477845,1,1502849161477851,1502849161477850,1502849161478177,1502849161477850,1502849161478249,1502849161478173,1502849161477844,,,,,,,,,,,, "MyOutboundMesage",10000,"20170816-02:06:01.478",1502849161478105,1502849161478172,1502849161478173,1502849161478316,1502849161478172,1502849161478125,1502849161478309,1502849161478170,1502849161478102,,,,,,,,,,1502849161478224,1,1502849161478235,1502849161478223,1502849161478145,1502849161478172,1502849161478140,1502849161478129,1502849161478232,1502849161478208,1502849161478224,1 |
Each TsMicros timestamps 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
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.
Outbound Message Timings
- Not all timestamps captured when binding uses a detached sending thread.
- Not all timestamps captured for BestEffort sends on a binding that does buffering of messages.