Anchor
_Toc221568551 _Toc221568551

Overview

An operational XVM continuously collects raw statistics during the course of its operation. The xvm can also be configured to spin up a background thread that periodically performs the following:

1. Perform Performs higher level statistical computations such as calculate calculating message rates and average latencies.
2. Emits heartbeat messages to be processed by handlers.
3. Optionally outputs server statistics rendered stats to named trace loggers using the platform's tracing and logging system.a trace logger which is useful in testing and diagnose situations. 
4. Optionally writes heartbeat messages containing useful server-wide statistics to a binary transaction log (with zero steady-state allocations) .Detect violation/abatement of alert thresholds and dispatch appropriate alert events.which is useful for zero garbage capture of performance in production. 

The raw metrics are collected by the server are used by the background statistical thread for its computations and can also be retrieved programatically programmatically by an application for its own use.
In this document, we

...

describe:

• how enable and configure xvm stats collection and emission. 
• the higher level statistics calculations performed by the statistics thread,
• Describe and the format of the output of the statistics thread.

Configuration Settings

Enabling Heartbeats

Heartbeats for an XVM can be enabled via DDL XML using the <heartbeats> element: 

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <collectNonZGStats>true</collectNonZGStats>
      <collectIndividualThreadStats>true</collectIndividualThreadStats>
      <collectSeriesStats>true</collectSeriesStats>
      <collectSeriesDatapoints>false</collectSeriesDatapoints>
      <maxTrackableSeriesValue>100000000</maxTrackableSeriesValue>
      <includeMessageTypeStats>false</includeMessageTypeStats>
      <collectPoolStats>true</collectPoolStats>
      <poolDepletionThreshold>1.0</poolDepletionThreshold>
      <logging enabled="true"></logging>
      <tracing enabled="true"></tracing>
    </heartbeats>
  </xvm>
</xvms>

...

enabled

interval

collectNonZGStats

collectIndividualThreadStats

collectSeriesStats

collectSeriesDatapoints

maxTrackableSeriesValue

includeMessageTypeStats

collectPoolStats

poolDepletionThreshold

Handling Server Heartbeats

When heartbeats are enabled via the nv.server.stats.enable and nv.server.stats.interval properties they can be handled in several ways:

logging

tracing

Enabling Global Stats

An XVM collects stats that are enabled for the applications that it contains. The followings stats can be enabled and reported in heartbeats

Environment Properties

<env>
  <!-- global stats properties -->
  <nv>
    <stats.latencymanager.samplesize>65536</stats.latencymanager.samplesize>
    <msg.latency.stats>true</msg.latency.stats>
    <ods.latency.stats>true</ods.latency.stats>
    <link.network.stampiots>true</link.network.stampiots>
  </nv>
</env>

Engine Stats

The xvm statistics thread will collect the following latency stats from the apps it contains when they are enabled

<apps>
  <app name="my-app" ...>
    <captureTransactionLatencyStats>true</captureTransactionLatencyStats>
    <captureEventLatencyStats>true</captureEventLatencyStats>
    <captureMessageTypeStats>false</captureMessageTypeStats>
  </app>
</apps>

 See Also: 

• DDL Reference for more details about the above stats. 
• AEP Engine Statistics for more detail about app-level stats.

Handling XVM Heartbeats

When heartbeats are enabled they can be consumed or emitted in several ways, discussed below.

Heartbeat Tracing

By default all server statistics tracers are disabled as trace logging is not zero garbage and introduce introduces cpu overhead in computing statistics. While tracing heartbeats isn't recommended in production, enabling server statistics trace output can be useful for debugging and performance tuning. To enable you will need to configure the appropriate tracers at the debug level. See the Heartbeat Trace Output Trace Loggers section for more detail.

...

<xvms>
  <xvmname="my-xvm">
    <heartbeats enabled="true" interval="5">
      <logging enabled="true"></logging>
      <tracing enabled="true"></tracing>
    </heartbeats>
  </xvm>
</xvms>

Heartbeat Logging

Applications that are latency sensitive might prefer to leave all tracers disabled to avoid unnecessary allocations and the associated GC activity. As an alternative, it's possible to enable logging of zero-garbage heartbeat messages to a binary transaction log:

<?xml version="1.0" encoding="utf-8"?>
<model xmlns="http://www.neeveresearch.com/schema/x-ddl" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"<xvms>
  <xvm name="my-xvm">
    <!-- ... snip ... -->
    <servers>
        <!-- ... -->
        <server name="..." group="...<heartbeats enabled="true" interval="5">
            <!-- ... -->
            <heartbeatLogging <logging enabled="true">
                <storeRoot>/path/to/heartbeat/log/directory</storeRoot>
            </heartbeatLogging>logging>
            <!-- ... -->
        </server>
        <!-- ... -->
    </servers>
    <!-- ... snip ... -->
</model>

...

</heartbeats>
  </xvm>
</xvms>

When a storeRoot is not set, an XVM will log heartbeats to {XRuntime.getDataDirectory}/server-heartbeats/<xvm-name>-heartbeats.log, which can then be queried and traced from a separate process using the Stats Dump Tool.

 Note that at this time binary heartbeat logs do not support rolling collection. .. so at this time the built in hearbeat logging Consequently this mechanism is not suitable for long running application instances.

 See Also: 

• DDL Reference for more options that can be used to configure heartbeat logging. 

Heartbeat Event Handlers

Your application can register an event handler for server heartbeats to handle them in process. 

...

See the SrvMonHeartbeatMessage JavaDoc for API details. 

...

Admin Clients

A Lumino or Robin Controller controller can also be used to connect to a server and via a direct admin connection over TCP to listen for heartbeats emitted by a Talon Serverfor monitoring purposes. The XVMs stats thread will queue copies of each emitted heartbeats to each connected admin client. 

Anchor
_

...

Toc221568564 _

...

The server statistics thread performs the following operations:

1. Compute higher level statistics such as metric averages
2. Output raw and computed statistics to any trace loggers configured at the debug level
3. Emit heartbeat messages consumed by handlers and the heartbeat log, if enabled

The statistics thread can be enabled or disabled via the configuration parameters.

...

The server statistics thread can also be started via the following environment variables or system properties:

nv.server.stats.enable=true

Once started administratively, the statistics thread remains active until the server is stopped.

...

By default, the server statistics thread collects object pool stats. If you would prefer pool stats not to be recorded:

nv.server.stats.pool.enable=false

...

The server statistics thread computes (then optionally traces and/or logs) the following at the configured frequency:

...

Toc221568564

Heartbeat Trace Output

Heartbeat trace is emitted to the nv.server.heartbeat logger at a level of INFO. Trace is only emitted for the types of heartbeat trace for which tracing has been enabled. This section discusses the various types of heartbeat trace, how the trace for those types is enabled and an explanation on the trace output for each of the types. 

 See Also: 

• X Platform Tracing and Logging for general information on trace logging. 

System Stats

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <tracing enabled="true">
        <traceSysStats>true</traceSysStats>
      </tracing>
    </heartbeats>
  </xvm>
</xvms>

Sample Trace Output

[System Stats]
Sat May 13 12:14:03 PDT 2017 'market' server (pid=54449) 2 apps (collection time=0 ns)
System: 20 processors, load average: 0.73 (load 0.10 process, 0.10 total system)
Memory (system): 94.4G total, 89.8G free, 5.5G committed (Swap: 96.6G total, 96.6G free)
Memory (proc): HEAP 1.5G init, 522M used, 1.5G commit, 1.5G max NON-HEAP 2M init, 47M used, 48M commit, 0K max
Disk:
  [/ Total: 49.2GB, Usable:  18GB, Free:  18GB]
  [/dev/shm Total: 47.2GB, Usable: 47.2GB, Free: 47.2GB]
  [/boot Total: 484.2MB, Usable: 422.4MB, Free: 422.4MB]
  [/home Total: 405.2GB, Usable: 267GB, Free: 267GB]
  [/distributions Total: 196.9GB, Usable: 8.1GB, Free: 8.1GB]
Threads: 20 total (16 daemon) 21 peak
JIT: HotSpot 64-Bit Tiered Compilers, time: 2959 ms
GC:
...ParNew [0 collections, commulative time: 0 ms]
...MarkSweepCompact [1 collections, commulative time: 54 ms]

The above trace can be interpreted as follows:

General Info

• Date and time that statistics gathering started
• Server name
• Server PID
• Number of apps running in the server
• Time spent gathering server statistics (for the current interval, excluding formatting)

System Info

• Number of available processors
• System load average

Memory Info

For the entire system:

• Total available memory
• The free memory
• Commit memory
• Swap total/free 

For the process:

• Initial heap size
• Heap used
• Heap committed
• Max heap size
• Initial non-heap size
• Non-heap memory used
• Non-heap memory committed
• Non-heap memory max size

 For more info regarding the process statistics above, you can reference the Oracle JavaDoc on MemoryUsage.

 JDK 7 or newer is needed to collect all available memory stats. In addition some stats are not available on all jvms. 

Disk

For each volume available:

• Total space
• Usable space
• Available space.

 Listing of disk system roots required JDK7+, with JDK 6 or below, some disk information may not be available. 

Thread Info

• Total thread count
• Daemon thread count
• Peak thread count

JIT Info

• JIT name

• Total compilation time

GC Info

• Collection count (for all GCs)
• Collection time (for all GCs)

Thread Stats

Reported for each active thread:

• Per-thread CPU time as a percentage of total CPU time
• Per-thread user CPU time as a percentage of thread CPU time
• Delta CPU time
• Delta CPU time as a percentage of total delta CPU time
• Delta user CPU time
• Delta user CPU time as a percentage of thread delta CPU time

Pool Stats

To reduce the size of heartbeats Pool Stats for a given pool are only included when:

• A miss has been recorded for the pool in a given interval and it results in a new object being allocated. 
• The number of preallocated obects taken from a pool drops below the configured value for the pool depletion threshold.

Pool stats include: 

• Number of puts
• Delta number of puts
• Number of gets
• Delta number of gets
• Number of hits
• Delta number of hits
• Number of misses
• Delta number of misses
• Number of growths
• Delta number of growths
• Number of evicts
• Delta number of evicts
• Number of detached watches
• Delta number of detached watches
• Pool size
• Number of preallocated objects (????)
• Pool capacity
• Pool key

App Stats

Reported for each app:

• Engine stats
• Store stats
• Store binding persister stats
• Store binding ICR sender stats
• Bus binding stats
• User stats

 See Also: 

• AEP Engine Statistics for more detail about app-level stats.
• User Defined App Stats for adding stats specific to your application to heartbeats.

...

The server statistics thread uses several named trace loggers to log the raw and computed statistics output. The following is the list of the loggers used by the server stats thread:

• nv.server.stats.sys.trace – tracer for System Statistics
• nv.server.stats.thread.trace – tracer for Thread Statistics
• nv.server.stats.pool.trace – tracer for Pool Statistics
• nv.server.stats.app.trace – tracer for Application and Engine Statistics
• nv.server.stats.userstats.trace – tracer for User Defined Statistics

If you would like to see server statistics trace output, the appropriate tracers need to be configured at the debug level. For example, too enable System Stats trace output:

nv.server.stats.sys.trace=debug

 See Also: X Platform Tracing and Logging for general details on configuration of trace logging. 

...

System Stats

Appears in trace output when nv.server.stats.enable=true and nv.server.stats.sys.trace=debug

[System Stats]
Tue Jun 28 17:26:03 PDT 2016 'ems1' server (pid=50360) 2 apps (collection time=73982839 ns)
System: 20 processors load average: 2.30
Memory: HEAP 8.0G init 6.6G used 7.8G commit 7.8G max NON-HEAP 2M init 44M used 46M commit 0K max
Threads: 26 total (23 daemon) 27 peak
JIT: HotSpot 64-Bit Tiered Compilers, time: 11997 ms
[6 6404 ms] [2 8771 ms]

Thread Stats

Appears in trace output when nv.server.stats.enable=true and nv.server.stats.thread.trace=debug

Thread Stats

Individual thread stats can be traced by setting the following in DDL:

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <collectIndividualThreadStats>true</collectIndividualThreadStats>
      <tracing enabled="true">
        <traceThreadStats>true</traceThreadStats>
      </tracing>
    </heartbeats>
  </xvm>
</xvms>

Sample Trace Output

[Thread Stats]
ID    CPU       DCPU    DUSER   CPU%  USER% WAIT% STATE           NAME
1     6.0s      982.8us 0       1     0     0     RUNNABLE        X-Server-blackbird1-Main (aff=[])

2     9.3ms     0 

     0       0     0     0     WAITING         Reference Handler

3     8.7ms     0 

     0       0     0     0     WAITING 

        Finalizer
4     43.8us    0       0       0     0     0     RUNNABLE        Signal Dispatcher
23    53.9ms    722.7us 0       1     0     0     RUNNABLE        X-EDP-McastReceiver (aff=[1(s0c1t0)])

24 

  26.3ms    426.5us 0       1     0     0     TIMED_WAITING   X-EDP-Timer (aff=[1(s0c1t0)])

26 

1.9s 

   33.9ms  30.0ms  1     1     0     RUNNABLE        X-Server-blackbird1-StatsRunner (aff=[1(s0c1t0)])

28 

6.9m 

  10.2s   4.8s    100 

48 

  0 

RUNNABLE        X-Server-

blackbird1-IOThread-1 (aff=[8(s0c11t0)])

30    236.6us   0 

     0       0     0     0     TIMED_WAITING   X-EventMultiplexer-Wakeup-admin (aff=[1(s0c1t0)])

34 

685.4ms 

 11.5ms  0 

    1     0     0 

    TIMED_WAITING   X-

EventMultiplexer-

Wakeup-blackbird (aff=[1(s0c1t0)])

35 

  9.2m      10.3s   10.3s   100   100   100   RUNNABLE        X-ODS-StoreLog-blackbird-1 (aff=[

4(

s0c4t0)])

40 

  9.2m      10.3s   10.3s   100   100   0     RUNNABLE        SorProcessor (aff=[

5(

s0c8t0)])

41    11.7ms    0 

     0       0     0 

    100   WAITING         X-STEMux-admin-1 (aff=[

])

42 

  9.0m      10.3s   10.2s   100   99    90    RUNNABLE        X-STEMux-blackbird-2 (aff=[

2(

s0c2t0)])

43 

  7.0m      10.2s   4.8s    100   47    0     RUNNABLE        X-ODS-StoreReplicatorLinkReader-myapp-93323c0d-5e4c-48d7-8cd4-f251963a6310 (aff=[

3(

s0c3t0)])

44 

 52.0ms    973.7us 0       1     0     0     RUNNABLE        X-ODS-StoreLinkAcceptor-1 (aff=[1(s0c1t0)])

45 

58.9ms 

1.0ms   0       1     0     0     RUNNABLE        X-EDP-McastReceiver (aff=[

1(

s0c1t0)])

46 

  41.9ms    592.2us 0       1     0     0     TIMED_WAITING   X-EDP-Timer (aff=[1(s0c1t0)])

48 

  9.1m      10.3s   10.1s   100   98    98    RUNNABLE        X-AEP-BusManager-IO-blackbird.market (aff=[

7(

s0c10t0)])

49    1.1s      0 

     0       0     0     0     RUNNABLE        X-

Client-

LinkManagerReader[c43b3977-

572f-4366-8524-f17678e71515] (aff=[

9(

s0c12t0)])

50 

  9.1m      10.3s   10.3s   100   100   93    RUNNABLE        X-AEP-BusManager-IO-blackbird.blackbird (aff=[

6(

s0c9t0)])

Pool Stats

Appears in trace output when nv.server.stats.enable=true and nv.server.stats.pool.trace=debug

<27,50360,perf5.neeveresearch.com> 20160628-17:26:03:609 (dbg)...
[Pool Stats]
PUT DPUT GET DGET HIT DHIT MISS DMISS GROW DGROW EVIC DEVIC DWSH DDWSH SIZE PRE CAP NAME
0 0 1 0 0 0 1 0 0 0 0 0 0 0 0 0 1024 packet.server_client_connect_request.71
0 0 1 0 0 0 1 0 0 0 0 0 0 0 0 0 1024 packet.server_client_connect_reply.50
46 0 46 0 44 0 2 0 0 0 0 0 0 0 2 0 1024 iobuf.heap-256.4
4 0 145 0 4 0 141 0 0 0 0 0 0 0 0 0 1024 iobuf.native-256.23
49 0 64 0 48 0 16 0 0 0 0 0 0 0 1 0 1024 iobuf.heap-64.2
18 0 27.3M 0 18 0 27.3M 0 0 0 0 0 0 0 0 0 1024 iobuf.native-32.20
6 0 29 0 6 0 23 0 0 0 0 0 0 0 0 0 1024 iobuf.native-64.21
0 0 5 0 0 0 5 0 0 0 0 0 0 0 0 0 1024 packet.recovery_log_eof_marker.87
0 0 2 0 0 0 2 0 0 0 0 0 0 0 0 0 1024 packet.recovery_log_checkpoint_state.39
48 0 48 0 46 0 2 0 0 0 0 0 0 0 2 0 1024 packet.discovery_esa.65
2 0 33 0 2 0 31 0 0 0 0 0 0 0 0 0 1024 iobuf.heap-32.1
0 0 2 0 0 0 2 0 0 0 0 0 0 0 0 0 1024 iobuf.native-8K.28
0 0 2 0 0 0 2 0 0 0 0 0 0 0 0 0 1024 xbuf.entity.SrvMonAppInfoXbufEntity.0.100.106

App Stats and User Stats

...

Where columns can be interpreted as:

Column	Description
ID	The thread's id
CPU	The total amount of time in nanoseconds that the thread has executed (as reported by the JMX thread bean)
DCPU	The amount of time that the thread has executed in user mode or system mode (as reported by the JMX thread bean)
DUSER	The amount of time that the thread has executed in user mode in the given interval in nanoseconds (as reported by the JMX thread bean)
CPU%	The percentage of cpu time the thread used during the interval (e.g. DCPU * 100 / interval time)
USER%	The percentage of user mode cpu time the thread used during the interval (e.g. DCPU * 100 / interval time)
WAIT%	The percentage of the time that the thread was recorded in a wait state such as a busy spin loop or a disruptor wait. Wait times are proactively captured by the platform via code instrumentation that takes a timestamp before and after entering/exiting the wait condition. This means that unlike CPU% or USER%, this percentage can include time when the thread is not using scheduled and consuming cpu resources. Because of this It is not generally possible to simply subtract WAIT% from CPU% to calculate the amount of time the thread actually executed. For example if CPU% is 50 and WAIT% is also 50 and the interval is 5 seconds, it could be that 2.5 seconds of real work was done while 2.5 seconds of wait time occurred while the thread was context switched out, or it could be that all 2.5 seconds of wait time coincided with the 2.5 seconds of of cpu time and all of the cpu time was spent busy spinning. In other words, WAIT% gives a definitive indication of time that the thread was not doing active work during the interval, the remaining cpu time is at the mercy of the operating systems thread scheduler.
STATE	The thread's runnable state at the time of collection
NAME	The thread name. Note that when affinitization is enabled and the thread has been affinitized, that affinitization information is append to the thread name. This is useful when trying to determine whether a thread should be affinitized. A Busy spinning thread will typically have a CPU% of ~100. If the thread is not affinitized, it might be a good candidate.
affinity	The affinity summary string reported along with individual thread stats is not reported in a column of its own as the affinitizer appends it the thread name.

CPU times are reported according to the most appropriate short form of:

Pool Stats

Pools stats can be traced by setting the following in DDL:

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <collectPoolStats>true</collectPoolStats>
      <tracing enabled="true">
        <tracePoolStats>true</tracePoolStats>
      </tracing>
    </heartbeats>
  </xvm>
</xvms>

To reduce the size of heartbeats, Pool Stats for a given pool are only included when:

• A miss has been recorded for the pool in a given interval and it results in a new object being allocated. 
• The number of preallocated obects taken from a pool drops below the configured value for the pool depletion threshold.

Sample Trace Output

[Pool Stats]
PUT   DPUT  GET   DGET  HIT   DHIT  MISS  DMISS GROW  DGROW EVIC  DEVIC DWSH  DDWSH SIZE  PRE   CAP   NAME
38    0     16.8M 0     38    0     16.8M 0     0     0     0     0     0     0     0     0     1024  iobuf.native-32.20
1     0     62    0     1     0     61    0     0     0     0     0     0     0     0     0     1024  iobuf.native-64.21
1     0     1.0M  0     1     0     1.0M  0     0     0     0     0     0     0     0     0     1024  iobuf.native-256.23
7     0     75    0     7     0     68    0     0     0     0     0     0     0     0     0     1024  iobuf.heap-32.1

Engine Stats

Stats collected by the AEP engine underlying your application are also included in heartbeats. Tracing of engine stats can be enabled with the following. 

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <tracing enabled="true">
        <traceAppStats>true</traceAppStats>
      </tracing>
    </heartbeats>
  </xvm>
</xvms>

See AEP Engine Statistics for more detail about engine stats.

User Stats

User stats collected by your application are also included in heartbeats. Tracing of user stats can be enabled with the following. 

<xvms>
  <xvm name="my-xvm">
    <heartbeats enabled="true" interval="5">
      <tracing enabled="true">
        <traceUserStats>true</traceUserStats>
      </tracing>
    </heartbeats>
  </xvm>
</xvms>

Sample Trace Output

[App (ems) User Stats]

...Gauges{

......EMS Messages Received: 142604

......EMS Orders Received: 35651

...}

...Series{

......[In Proc Tick To Trade(sno=35651, #points=150, #skipped=0)

.........In Proc Tick To Trade(interval): [sample=150, min=72 max=84 mean=75 median=75 75%ile=77 90%ile=79 99%ile=83 99.9%ile=84 99.99%ile=84]

.........In Proc Tick To Trade (running): [sample=35651, min=72 max=

2000 mean=93 median=76 75%ile=82 90%ile=111 99%ile=227 99.9%ile=805 99.99%ile=

1197]

......[In Proc Time To First Slice(sno=35651, #points=150, #skipped=0)

.........In Proc Time To First Slice(interval): [sample=150, min=85 max=98 mean=88 median=88 75%ile=90 90%ile=92 99%ile=95 99.9%ile=98 99.99%ile=98]

.........In Proc Time To First Slice (running): [sample=35651, min=84 max=

4469 mean=249 median=88 75%ile=95 90%ile=133 99%ile=283 99.9%ile=

3628 99.99%ile=

4143]

...}

 See Also: 

• User Defined App Stats for adding stats specific to your application to heartbeats.