...
An operational AEP engine and its underlying components such as its HA Store and Bus Bindings can be configured to continuously collect many raw statistics during the course of its operation. Such stats can be reported by an a Talon Server XVM and reported in a zero garbage fashion in the form of server heartbeats. Additionally for quick debugging and diagnostic purporses the engine can spin up a background thread that periodically performs the following:
...
- the various raw metrics captured by an engine,
- how to switch on and configure the statistics thread operation,the higher level statistics calculations performed by the statistics thread,
- and the format of the output of the statistics thread.
Configuration Settings
Global Latency Stats
...
Settings
Most engine metrics are collected by default and cannot be disabled. Latency statistics, however, or more expensive to collect and can impact application performance. Consequently, the platform provides several knobs to allow applications to control what latency statistics are collected and balance the performance cost against operational visibility. The table below summarizes the various stats collection that can be enabled.configuration settings that control latency collection at a process-wide level.
| Configuration Setting | Default | Description | ||||
|---|---|---|---|---|---|---|
| nv. | aep.<engine>.latency.stats | false | Indicates whether or not latency stats for the engine should be collected. | The latency stats include transaction level latencies that can be used in monitoring the overall latencies of the various legs of a transaction.nv.stats.series.samplesize | 10240 | Property that can be used to control the default sampling size for series stats. If the number of datapoints collected in a stats interval exceeds this size, the computation for histographical data will be lossy. Increasing the value reduces loss of datapoints, but results in greater overhead in stats collection in terms of both memory usage and pressure on the process caches. |
| nv. | aepmsg. | <engine>latency. | msgtype.stats | false | Indicates whether or not per-message-type statistics should be collected. When enabled, processing latencies are recorded on a per message basis. Per message type stats introduce a fair amount of overhead, so typically enabling their collection is enabled only during application profiling for application with stringent performance requirements. | |
| nv.aep.<engine>.event.latency.stats | false | Indicates whether or not per-event-type latency statistics should be included in a given engine's stats trace output. Event latency statistics can be used to capture the processing latencies for each type of event being processed in the engine. This is useful in determining if particular event types are consuming considerable engine thread processing time. Per event type stats introduce a fair amount of overhead, so typically enabling their collection is enabled only during application profiling for application with stringent performance requirements. | ||||
| nv.msg.latency.stats | false | Property that enabled message latency stats tracking. Property that globally enables collection of message latency stats as messages flow through the system. These statistics include latencies in the flow outside of transaction processing. For received messages these statistics include transmission, deserialization and dispatch costs. For sent messages these include serialization and transmission costs. When set to true, timings for messages are captured as they flow through the system. Enablement of these stats is required to collect message bus latency stats. Enabling this property can increase latency due to the overhead of tracking timestamps. | ||||
| nv.msgtype.latency.stats | false | Property that enabled per enables tracking of message type latency stats trackingon a type by type basis. When set to true, timings for each message type are individually tracked as separate stats. This can be useful in tracking down issues in which a particular message type is problematic (for example, tracking down a high application handler message processing time). However, it results in a higher overhead
| ||||
| nv.ods.latency.stats | false | Indicates whether or not store latency statistics are captured. Store latency stats expose statistics related to serializing replicating and persisting transactions.
| ||||
| nv.event.latency.stats | false | Indicates whether or not event latency statistics are captured. Enabling Event latency stats record timestamps for enqueue and dequeue of events across event multiplexer, such as the AepEngine's input multiplexer queue. Enabling event latency stats is useful for determining if an engine's event multiplexer queue is backing up by recording the time that events remain on the input queue.
| ||||
| nv.link.network.stampiots | false | Indicates whether or not timestamps should be stamped on inbound and outbound messages. Disabled by default. Enabling this setting will allow engines to provide more detail in the form of transaction legs in message latency statistics. |
Statistics Output Threads
...
|
...
| Configuration Setting | Default | Description |
|---|---|---|
| nv.aep.<engine>.stats.interval | 0 | The interval (in seconds) at which engine stats will be traced for a given engine. Can be set to a positive integer indicate the period in seconds at which the engine's stats dump thread will dump recorded engine statistics. Setting a value of 0 disables creation of the stats thread. When enabled, engine stats are traced to the logger 'nv.aep.engine.stats' at a level of NOTE: disabling the engine stats thread only stops stats from being periodically traced. It does not stop the engine from collecting stats; stats can still be collected by an external thread (such as the Talon Server which reports the stats in server heartbeats). In other words, enabling the stats thread is not a prerequisite for collecting stats, and disabling the stats reporting thread does not stop them from being collected. NOTE: while collection of engine stats is a zero garbage operation, tracing engine stats is not a zero garbage when performed by this stats thread. For latency sensitive apps, it is recommended to run in a Talon server which can collect engine stats and report them in heartbeats in a zero garbage fashion. |
| nv.aep.<engine>.sysstats.interval | 0 | The interval (in seconds) at which engine sys stats will be reported. Set to 0 (the default) to completely disable sys stats tracing for a given engine. In most cases, AEP sys stats will not be used and system level stats would be recorded in the Server Statistics from which an AEPEngine is running. |
| nv.event.mux.<name>.stats.interval | 0 | The interval (in seconds) at which multiplexer stats will be traced. Multiplexer stats can also be reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. |
| nv.msg.latency.stats.interval | 0 | The interval (in seconds) at which message latency stats are traced. This setting has no effect if nv.msg.latency.stats is false. This allows granular tracing of just message latency stats on a per bus basis. Message latency stats can also be reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. |
| nv.aep.busmanager.<engine>.<bus>.stats.interval | 0 | The interval (in seconds) at which bus stats will be traced. Bus stats reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. When engine stats output is disabled this can be used to trace only bus stats for a particular message bus. |
report 'wire' times for an application's store. |
The above settings can be configured in config.xml as follows:
| Code Block | ||||
|---|---|---|---|---|
| ||||
<env>
<nv>
<msg.latency.stats>true</msg.latency.stats>
<event.latency.stats>true</event.latency.stats>
<ods.latency.stats>true</ods.latency.stats>
<link.network.stampiots>true</link.network.stampiots>
<latencymanager.samplesize>10240</latencymanager.samplesize>
</nv>
</env> |
Per Engine Stats Settings
Latencies related to a particular application's transaction pipeline can be configured
| Configuration Setting | Default | Description |
|---|---|---|
captureTransactionLatencyStats | 10240 | Property that can be used to control the default sampling size for series stats. If the number of datapoints collected in a stats interval exceeds this size, the computation for histographical data will be lossy. Increasing the value reduces loss of datapoints, but results in greater overhead in stats collection in terms of both memory usage and pressure on the process caches. |
captureEventLatencyStats | false | Property that globally enables collection of message latency stats as messages flow through the system. These statistics include latencies in the flow outside of transaction processing. For received messages these statistics include transmission, deserialization and dispatch costs. For sent messages these include serialization and transmission costs. When set to true, timings for messages are captured as they flow through the system. Enablement of these stats is required to collect message bus latency stats. Enabling this property can increase latency due to the overhead of tracking timestamps. |
captureMessageTypeStats | false | Property that enables tracking of message statistics on a per message type basis. When set to true, timings for each message type are individually tracked as separate stats
|
messageTypeStatsLatenciesToCapture | all | Property that enables tracking of latency statistics on a per message type ba Property controlling which latency stats on a per message type basis. This property is specified as a comma separated
The values 'all' or 'none' may not be combined with other values. This value only applies when captureMessageTypeStats is true. When not specified the value defaults to all. |
capturePerTransactionStats perTransactionStatsLogging | false | Configuration See Per Transaction Stats for more details. |
Below is example of enabl
| Code Block | ||||
|---|---|---|---|---|
| ||||
<apps>
<templates>
<app name="app-template">
<captureTransactionLatencyStats>true</captureTransactionLatencyStats>
<captureEventLatencyStats>true</captureEventLatencyStats>
<captureMessageTypeStats>true</captureMessageTypeStats>
<messageTypeStatLatenciesToCapture>c2o,o2p,mpproc,mproc,mfilt</messageTypeStatLatenciesToCapture>
<capturePerTransactionStats>false</capturePerTransactionStats>
<perTransactionStatsLogging policy="Off">
<detachedWrite enabled="true"></detachedWrite>
</perTransactionStatsLogging>
</app>
</templates>
</apps> |
| Anchor | ||||
|---|---|---|---|---|
|
...
Metric | Description |
NumFlows | Total number of message flows functioning in the engine. |
NumMsgsRcvdBestEffort | Total number of messages received by the engine on best-effort channels. |
NumMsgsRcvdGuaranteed | Total number of messages received by the engine on guaranteed channels. |
NumMsgsSourced | [EventSourcing Only] |
| NumMsgsFiltered | The number of messages that were filtered. |
NumDupMsgsRcvd | Total number of duplicate messages received and discarded by an engine. This metric will always be 0 if duplicate detection has been disabled via the nv.aep.duplicate.checking configuration property. |
NumMsgsSentBestEffort | Total number of messages sent by the engine on best-effort channels. |
NumMsgsSentGuaranteed | Total number of messages sent by the engine on guaranteed channels. |
NumMsgsResent | Total number of messages retransmitted by an engine. |
NumEventsRcvd | Total number of events received by an engine. |
NumFlowEventsRcvd | Total number of flow events received by the engine. |
NumFlowEventsProcSuccess | Total number of successfully processed flow events. |
NumFlowEventsProcFail | Total number of failed flow events. |
NumFlowEventsProcComplete | Total number of flow events whose transactions have completed. |
NumTransactions | Total number of transactions that have been committed or rolled back. |
NumCommitsStarted | Total number of transactions whose commits have been started. |
NumCommitsCompleted | Total number of transactions whose commits have completed. |
NumSendCommitsStarted | Total number of transactions whose send commits have been started. |
NumSendCommitsCompleted | Total number of transactions whose send commits have completed. |
SendCommitCompletionQueueSize | Number of transaction in the send commit completion queue. |
NumStoreCommitsStarted | Total number of transactions whose store commits have been started. |
NumStoreCommitsCompleted | Total number of transactions whose store commits have completed. |
StoreCommitCompletionQueueSize | Number of transaction in the store commit completion queue. |
NumRollbacks | Number of transactions that have been rolled back. |
BackupOutboundQueueSize | [EventSourcing Only] |
BackupOutboundLogQueueSize | [EventSourcing Only] |
OutboundSno | The current outbound sequence number in use by the engine. |
OutboundStableSno | The current 'stable' outbound sequence number. |
Message Type Specific Statistics | Message type specific statistics.
|
...
The AEP engine's statistics thread performs the following operations:
- Computes higher level statistics such as metric averages.
- Outputs raw and computed statistics to a trace logger.
- Triggers alerts based on configured alert thresholds.
The statistics thread can be started/stopped either programmatically or via configuration parameters.
...
Each AepEngine object is associated with an AepEngineStats object that can be obtained from the engine as follows:
AepEngine.getStats()
An application can start and stop the statistics thread using the startPeriodicOutput() and stopPeriodicOutput() methods respectively exported Each AepEngineStats object. For example, the following would start the statistics thread with a periodic output and alert dispatch every 1 second.
AepEngineStats.startPeriodicOutput(1)
Correspondingly, the following would stop the statistics thread
AepEngineStats.stopPeriodicOutput()
...
An AEP engine's statistics thread can also be started via the following environment variable or system property.
nv.aep.<engineName>.stats.interval=<interval in seconds>
For example, the following would start the 'forwarder' AEP engine's statistics thread with a periodic output and alert frequency of 5 seconds.
nv.aep.forwarder.stats.interval=5
Once started administratively, the statistics thread remains active until the engine is stopped or the thread is programatically stopped.
| Note |
|---|
| Note: When configuring using environment variables, in Unix based systems where the shell does not support "." in environment variables, the "." can be replaced by "_". |
...
By default, an AEP engine does not collect message type specifc stats. To enable message type specific stats the following should be set in you DDL config:
...
<apps>
<app name="MyApp">
<captureMessageTypeStats>true</captureMessageTypeStats>
<app>
</apps
<xvms>
<xvm name="MyXVM">
<hearbeats enabled=true" interval="5">
<includeMessageTypeStats>true</includeMessageTypeStats>
</heartbeats>
</xvm>
<xvms>Transaction Latencies
Transaction latencies traced by an engine stats thread includes summary statistics for various phases within the transaction processing pipeline. The meaning of these summary statistics is as follows:
...
| Phase | Description |
|---|---|
| mpproc | Records the time (in microseconds) spent by the engine dispatching the message to an application. |
| mproc | Records latencies for application message process times (in an EventHandler). |
| mfilt | Records latencies for application message filtering times (by a message filter). |
| msend | Time spent in AepEngine.sendMessage(). The time in the AepEngine's send call. This latency will be a subset of mproc for solicited sends and it includes msendc. |
| msendc | Time spent in the AepEngine's core send logic. This leg includes enqueuing the message for delivery in the corresponding bus manager. |
| cstart | Time spent from the point the first message of a transaction is received to the time the transaction is committed. |
| cprolo | Time spent from the point where transaction commit is started to send or store commit, whichever occurs first. This latency measures the time taken in any bookkeeping done by the engine prior to commit the transaction to store (or for an engine without a store until outbound messages are released for delivery). |
| csend | The send commit latency: i.e. time from when send commit is initiated, to receipt of send completion event. This latency represents the time from when outbound messages for a transaction are released to the time that all acknowledgements for the messages are received. Because this latency includes acknowledgement time a high value for csend does not necessarily indicate that downstream latency will be affected. The Message Latencies listed below allow this value to be decomposied further. |
| ctrans | Time spent from the point the store commit completes to the beginning of the send commit which releases a transaction's outbound messages for delivery. If the engine doesn't have a store, then this statistic is not captured as messages are released immediately. |
| cstore | The store commit latency i.e. time from when store commit is initiated to receipt of store completion event. This latency includes the time spent serializing transaction contents, persisting to the store's transaction log, inter cluster replication, and replication to backup members including the replication ack.
|
| cepilo | Time spent from the point the store or the send commit completes, whichever is last, to commit completion. |
| cfull | Time spent from the time the first message of a transaction is received to commit completion. |
| tleg1 | Records latencies for the first transaction processing leg. Transaction Leg One includes time spent from the point where the first message of a transaction is received to submission of send/store commit. It includes message processing and and any overhead associated with transactional book keeping done by the engine.
|
tleg2 | Records latencies for the second transaction processing leg. Transaction Leg Two includes time spent from the point where the send/store commit completion is received to the submission of store/send commit.
|
| tleg3 | Records latencies for the third transaction processing leg. Transaction Leg Three includes time spent from the point where the store/store commit completion is received to the completion of the transaction commit.
|
| inout | Records latencies for receipt of a message to transmission of the last outbound message. |
| inack | Records latencies for receipt of a message to stabilization (and upstream acknowledgement for Guaranteed). |
| Anchor | ||||
|---|---|---|---|---|
|
By default, an AEP engine does not collect message type specifc stats. To enable message type specific stats the following should be set in you DDL config:
| Code Block | ||||
|---|---|---|---|---|
| ||||
<apps>
<app name="MyApp">
<captureMessageTypeStats>true</captureMessageTypeStats>
<app>
</apps
<xvms>
<xvm name="MyXVM">
<hearbeats enabled=true" interval="5">
<includeMessageTypeStats>true</includeMessageTypeStats>
</heartbeats>
</xvm>
<xvms> |
Bus Stats
The engine stats thread can also trace summary statistics for its message buses. Each message bus is wrapped by a Bus Manager which handles bus connect and reconnect, and also provides transactional semantics around the bus by queuing up messages that will be sent as part of an engine transaction. Each Bus Manager maintains statistics for across bus binding reconnects, allowing continuous stats across bus binding reconnects. The following sections break these statistics down in more detail.
...
| Phase | Description |
|---|---|
| c2o | The create to send latencies in microseconds, the time in microseconds from message creation to when send was called for it. |
| o2s | The send to serialize latencies in microseconds, the time from when the message was sent until it was serialized in preparation for transmission on the wire. For an engine with a store this will include the time from the application's send call, the replication hop (if there is a store) and time through the bus manager's disruptor if detached commit is enabled for the bus manager. |
| s | The serialize latencies in microseconds, the spent serializing the MessageView to its transport encoding. |
| s2w | The serialize to wire latencies in microseconds, the time post deserialize to just before the message is written to the wire. |
| w | The wire latencies in microseconds, the time an inbound messages spent on the wire. The time spent on the wire from when the message was written to the wire by the sender to the time it was received off the wire by the receiver. Note: that this metric is subject to clock skew when the sending and receiving sides are on different hosts. |
| w2d | The time from when the serialized form was received from the wire to deserialization. |
| d | The time (in microseconds) spent deserializing the message and wrapping it in a MessageView. |
| d2i | The time (in microseconds) from when the message was deserialized to when it is received by the engine. This measure the time from when the bus has deserialized by the bus to when the app's engine picks it up from it's input queue (before it dispatches it to an application) handler (it includes the o2p time of the engine's disruptor). Additional time spent by the engine dispatching the message to the application handler is covered by mpproc (see the Transaction Latencies table). |
| o2i | The origin to receive latencies in microseconds. The time from when a message was originally created to when it was received by the binding. |
| w2w | The wire to wire latencies in microseconds, for outbound messages the time from when the corresponding inbound message was received off the wire to when the outbound message was written to the wire. |
Event Multiplexer (Input Queue) Statistics
The Event Multiplexer reports statistics describing the latency between:
the The point at which an event is offered to the multiplexer by a thread and the point at which it is actually enqueued for processing – i.e. the o2p statistics traced per Feeder Queue.
Panel Feeder Queues (max=16, lastDecongest=0)
...X-Server-ems1-Main (aff=[]) has 0 (decongestCount=64500)
......[o2p] [sample=0, min=-1 max=-1 mean=-1 median=-1 75%ile=-1 90%ile=-1 99%ile=-1 99.9%ile=-1 99.99%ile=-1]
...X-ODS-StoreEventMultiplexer-1 (aff=[3(s0c3t0)]) has 0 (decongestCount=64492)
......[o2p] [sample=0, min=-1 max=-1 mean=-1 median=-1 75%ile=-1 90%ile=-1 99%ile=-1 99.9%ile=-1 99.99%ile=-1]the The time between when an event being enqueued is offered to the multiplexer for processing and actually being dequeued for processing by the multiplexer the time at which it is returned from a poll by the engine's event multiplexer thread for processing – i.e. the o2p statistics traced for the Event Multiplexer's Disruptor.
Panel [Event Multiplexer (ems)]
Disruptor (MultiThreadedSufficientCores, BusySpin)..
[0 of 1,024] 0%
...[o2p] [sample=0, min=-1 max=-1 mean=-1 median=-1 75%ile=-1 90%ile=-1 99%ile=-1 99.9%ile=-1 99.99%ile=-1]
...
An AEP engine's statistics thread uses a named trace logger to log the raw and computed statistics output. The following is the name of the logger used by an engine:
nv.aep.<engineName>.stats
For example, the 'forwarder' engine uses the following logger to log statistics output:
nv.aep.forwarder.stats
The configured logger can be either a native logger or an SLF4J logger. Refer to the X Platform Tracing and Logging document for details on X Platform trace loggers.
Appendinx A - Statistics Output Threads
The following output threads can be enabled to trace individual types of statistics, which is useful for testing and performance tuning. Enabling these output threads is not required for collecting stats. Statistics trace output is not zero garbage, so in a production scenario it usually makes more sense to collect stats via Xvm Heartbeats, which emits zero garbage heartbeats with the above statistics.
Configuration Setting | Default | Description |
|---|---|---|
| nv.aep.<engine>.stats.interval | 0 | The interval (in seconds) at which engine stats will be traced for a given engine. Can be set to a positive integer indicate the period in seconds at which the engine's stats dump thread will dump recorded engine statistics. Setting a value of 0 disables creation of the stats thread. When enabled, engine stats are traced to the logger 'nv.aep.engine.stats' at a level of NOTE: disabling the engine stats thread only stops stats from being periodically traced. It does not stop the engine from collecting stats; stats can still be collected by an external thread (such as the Talon Server which reports the stats in server heartbeats). In other words, enabling the stats thread is not a prerequisite for collecting stats, and disabling the stats reporting thread does not stop them from being collected. NOTE: while collection of engine stats is a zero garbage operation, tracing engine stats is not a zero garbage when performed by this stats thread. For latency sensitive apps, it is recommended to run in a Talon server which can collect engine stats and report them in heartbeats in a zero garbage fashion. |
| nv.aep.<engine>.sysstats.interval | 0 | The interval (in seconds) at which engine sys stats will be reported. Set to 0 (the default) to completely disable sys stats tracing for a given engine. In most cases, AEP sys stats will not be used and system level stats would be recorded in the Server Statistics from which an AEPEngine is running. |
| nv.event.mux.<name>.stats.interval | 0 | The interval (in seconds) at which multiplexer stats will be traced. Multiplexer stats can also be reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. |
| nv.msg.latency.stats.interval | 0 | The interval (in seconds) at which message latency stats are traced. This setting has no effect if nv.msg.latency.stats is false. This allows granular tracing of just message latency stats on a per bus basis. Message latency stats can also be reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. |
| nv.aep.busmanager.<engine>.<bus>.stats.interval | 0 | The interval (in seconds) at which bus stats will be traced. Bus stats reported as part of the overall engine stats from the engine stats thread, so there is no need to set this to a non-zero value if nv.aep.<engine>.stats.interval is greater than zero. When engine stats output is disabled this can be used to trace only bus stats for a particular message bus. |
| Anchor | ||||
|---|---|---|---|---|
|
...
B – Statistics Output Format
The following is a sample output of the statistics output by an AEP engine's statistics thread
...