...
| 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. |
...
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 collect collection collects timestamps recorded timestamps that are computed from capture 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:
...
| 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 ststarts |
| 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 omitted or set to 0. |
| sendCommitStartedTsMicros | Captures the time, in microseconds, at which outbound sends are committedcomitted. Message send commit still continues in the background. If the transaction does not contain outbound messages this may be ommitted omitted or set to 0. |
| sendCommitCompleteTsMicros | Captures the time, in microseconds, at which all sends have been written to their buses and acknowledged (if GuarantteedGuaranteed). If the transaction does not contain outbound messages this may be ommitted 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 assocated associated with inbound messages in the transaction. |
| outboundMessageTimings[] | Lists timings assocated associated with outbound messages in the transaction. |
...
| 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 expects all transaction logs that are to be queried to be located in the same folder and accepts 3 arguments:
- recoveryLogPath: The main receovery 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.
...