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

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 collect timestamps recorded timestamps that are computed from 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: 

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

Listing of Per Transaction Stats

The <appname>.txnstats.log will contain AepMonTransactionStatsMessages which has fields for general transaction stats and a listing of stats associated with each inbound and outbound message for the transaction. 

AepMonTransactionStats

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

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

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

The TransactionStatsLogTool  expects all transaction logs that are to be queried to be located in the same folder and accepts 3 arguments:

1. recoveryLogPath: The main receovery transaction log path, corresponding ".in.log" and ".out.log" and the "txnstats.log" are opened if they existing in the same directory. 
2. query: The transaction log query that selects entries from the logs. 
3. outputFileName: The name of the output file to which to write the results. 
   
   

java -cp "libs/*" com.neeve.tools.TransactionStatsLogTool -m rdat/processor.log "SELECT simpleClassName, transactionId, timestamp FROM logs WHERE transactionId BETWEEN 10000 and 10010" "rdat/txnstats.csv"

The above invocation would thus look for and open:

• processor.log
• processor.in.log
• processor.out.log
• 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 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.