The Talon Manual

Versions Compared

Old Version 24

changes.mady.by.user Girish Mutreja

Saved on

compared with

New Version Current

changes.mady.by.user Girish Mutreja

Saved on

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.

...

By default all server statistics tracers are disabled as trace logging is not zero garbage and 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.

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

...

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

Sample Trace Output

div
stylefont-size: smaller
No Format
[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]

...

Code Block
xml
xml
<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

div
stylefont-size: smaller
No Format
[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)])

...

  • 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

div
stylefont-size: smaller
No Format
[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
StatDescription

PUT

The overall number of times items were put (returned) to a pool.

DPUT

The number of times items were put (returned) to a pool since the last time the pool was reported in a heartbeat (the delta).

GET

The overall number of times an item was taken from a pool.

(lightbulb) If pool items are not being leaked, GET - PUT indicates the number of items that have been taken from the pool and not returned ... e.g. items that are being held by messages in the transaction processing pipeline or application state.

DGETThe number of times an item was taken from a pool since the last time the pool was reported in a heartbeat (the delta).
HITThe overall number of times that an item taken from a pool was satisfied by there being an available item in the pool.
DHITThe number of times that an item taken from a pool was satisfied by there being an available item in the pool since the last time the pool was reported in a heartbeat(the delta).
MISSThe overall number of times that an item taken from a pool was not satisfied by there being an available item in the pool resulting in an allocation.
DMISSThe number of times that an item taken from a pool was not satisfied by there being an available item in the pool resulting in an allocation since the last time the pool was reported in a heartbeat.
GROWThe overall number of times the capacity of a pool had to be increased to accomodate returned items.
DGROWThe number of times the capacity of a pool had to be increased to accomodate returned items since the last time the pool was reported in a heartbeat.

EVIC

The overall number of items that were evicted from the pool because the pool did not have an adequate capactiy to store them.
DEVICThe overall number of items that were evicted from the pool because the pool did not have an adequate capactiy to store them since the last time the pool was reported in a heartbeat.
DWSHThe overall number of times that an item return to the pool was washed (e.g. fields reset) in the detached pool washer thread.
DDWSHThe number of times that an item return to the pool was washed (e.g. fields reset) in the detached pool washer thread since the last time the pool was reported in a heartbeat
SIZE

The number of items that are currently in the pool available for pool gets. This number will be 0 if all objects that have been allocated by the pool have been taken.

(lightbulb) Note that because pool stats are generally printed when there are pool misses, this value will often be 0 reflecting that there are no items available in the pool

PREThe number of items initially preallocated for the pool.
CAP

The capacity of the backing array that is allocated to hold available pool items that have been preallocated or returned to the pool.

(lightbulb) The capacity of a pool will grow automatically as items are returned to the pool without being taken out. A large capacity generally indicates that at some point in the past a larger number of items was needed, but are not currently being used.

NAMEThe unique identifier for the pool.

...

Engine Stats

Stats that you defined in collected by the AEP engine underlying your application are emitted, they can be included in trace with the following configuration:also included in heartbeats. Tracing of engine stats can be enabled with the following. 

Code Block
xml
xml
<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. 

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

Sample Trace Output

div
stylefont-size: 10px;
No Format
[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]
...}

...

Aep Engine Stats

The aep engine stats underlying your application are also included in heartbeats. Tracing of aep 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>

Trace Output

The trace output

(info) See Also: