...

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 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 which provides the most granular view into the systemtherein at the cost of greater overhead. The sections below discuss how to enable per transaction stats , collection and how to dump them for that can be viewed for subsequent analysis. 

...

<env>
  <nv>
    <!-- globally enable message stats latency -->
    <msg.latency.stats>true</msg.latency.stats>
    <!-- Optionally, bump up the sample size for collected latency stats -->
    <stats.latencymanager.samplesize>65536</stats.latencymanager.samplesize>
    <!-- globally enable ODS store stats collection -->
    <ods.latency.stats>true</ods.latency.stats>
    <!-- Enable low level I/O timestamps-->
    <link.network.stampiots>true</link.network.stampiots>
  </nv>  
<env>

<apps>
  <app name="processor" mainClass="com.neeve.talon.starter.Application">
    <!-- Enable transaction latency stats collection --> 
    <captureTransactionLatencyStats>true</captureTransactionLatencyStats>
    <!-- Capture transaction stats on a per transaction basis --> 
    <capturePerTransactionStats>true</capturePerTransactionStats>
    <!-- Configure Per Transaction Stats Logger -->
    <perTransactionStatsLogging policy="UseDedicated">
      <flushOnCommit>true</flushOnCommit>\
      <detachedWrite enabled="true">
        <queueOfferStrategy>SingleThreaded</queueOfferStrategy>
        <queueWaitStrategy>Blocking</queueWaitStrategy>
        <queueDrainerCpuAffinityMask>0</queueDrainerCpuAffinityMask>
      </detachedWrite>
    </perTransactionStatsLogging>
  </app>
</apps>

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.

...

...

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 perf joins across logs, Talon includes a TransactionStatsLogTool which can be used to generate a comma separated values report of join the results of a transaction log query with the stats recorded above joined with a user supplied query based on the messages from recovery transaction log, inbound and outbound message logsin 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:

...

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. 

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 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. 

...

Epoch Offset Timestamps
When epoch offset timestamps are disabled 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.  

Outbound Message Timings

...

Additionally the TransactionStatsLogTool does not currently explicitly support checkpoint versioned logs.