Performance Metrics

• System Requirements
• Introduction
• Configuration
• Message Format
• Access Control
• List of Performance Metrics
• Application Performance Metrics
• ODBC Performance Metrics

System Requirements

Performance metrics are available in KCML 07.16.00.23055 or later for AIX 7 and Linux 2.6 (or later) and are depedent on the KCML Message Queue Support library, kmsgq.so.

Introduction

KCML has been instrumented to produce statistics on the performance of the application code. Statistics include processor utilization, memory usage and disk I/O, see List of Performance Metrics.

The statistics are sent, via kmsgq.so to a RabbitMQ server cluster where they can be processed, for example by populating an InfluxDB database. To reduce the impact of performance metrics it is advisable to have a fast network connection between the application server and the RabbitMQ server.

Each performance metric can be individually enabled by calling 'KCML_PerfMetric_Set() passing in one of the built-in KCML_PERFMETRIC_ flags. In KCML 7.16, or later, these flags are members of a KCML_PERFMETRICS enumeration. A performance metric can either be enabled for an individual partition or globally, for all partitions, by passing in a partition number of zero. A performance metric will be sent if its flag has been set either at a partition or global level. These flags are stored in same shared memory area as $PSTAT which must have been created by a KCML, or its utilities, that support performance metrics and with an extended $PSTAT configured.

REM Enable kcml.kdb.open on this partition
'KCML_PerfMetric_Set(_KCML_PERFMETRIC_KCML_KDB_OPEN, #PART, sToken$)

REM Enable kcml.session.start on all partitions
'KCML_PerfMetric_Set(_KCML_PERFMETRIC_KCML_SESSION_START, 0, sToken$)

Calling 'KCML_PerfMetric_Clear() will unset the flag, either for the specified partition or for all partitions.

The optional sToken$ parameter is intended for use on customer systems where only certain processes are expected to change the state of performance metrics.
See: Access Control

Applications can check what performance metrics are enabled by calling 'KCML_PerfMetric_Get(). This will return an array of KCML_PerfMetricRec records which contains the performance metrics name, its flag value and its state, ie enabled or disabled.

00010 REM Display global performance metrics
    : DIM a$(0)_kcml_perfmetricrec
    : DIM rc AS bool
    : DIM nCount AS Integer
    : DIM i AS Integer
    : DIM state$8
    : rc = 'kcml_perfmetric_get(BYREF a$(),0)
    : IF (rc)
    :     nCount = DIM(a$(),1)
    :     FOR i = 1 TO nCount
    :         state$ = (FLD(a$(i).kcml_perfmetric_enabled) ? "on" : "off")
    :         PRINT FLD(a$(i).kcml_perfmetric_name$);" = ";FLD(a$(i).kcml_perfmetric_flag);" = ";state$
    :     NEXT i
    : ELSE
    :     REM $PSTAT not large enough. Most likely created by an older version of KCML.
    :     PRINT "Performance metrics not available"
    : END IF
    : $END

Running the above example should display the state of each performance metric.

Configuration

By default the collection of performance metrics is disabled. To enable performance metrics the location, and credentials, to the RabbitMQ server and a named queue must be specified in /etc/kcml/msgq.conf. Systems that have been executed as a Connection Manager Service may also define their own configuration in /etc/kcml/msgq.$SERVICE.conf. If /etc/kcml/msgq.$SERVICE.conf does not exist then the configuration will be loaded from /etc/kcml/msgq.conf.

See KCML Message Queue Support library: Configuration.

Next configure KCML to use that queue for performance metrics by adding the following to msgq.conf

[perfmetric]
queue=myQueue

The [perfmetric] section can also have the following optional settings:-

mem=1024
logperiod=30
iotimerfreq=1000
decltimerfreq=50
maxdupidx=20000
lockwaitalert=5
maxtranstime=4
x509warndays=100

The mem setting will cause kcml.mem.delta to be reported for every allocation that exceeds the specified size, in kilobytes.
The logperiod value specifies the frequency, in seconds, that periodically logged metrics such as kcml.kdb.io & kcml.declare.total are reported.
Increasing the following key values of the [perfmetric] section can be used to reduce the overhead of determining how long ago the last periodic metrics were sent.

For example the above configuration will only check every 1000 read/write operations and every 50th $DECLARE call.
The maxdupidx value controls the sensitivity of the kcml.kdb.dupidxio metric. By default KCML will report this metric if 100000 index blocks are scanned when searching a table with duplicate indices. The above example lowers this limit to 20000 index blocks.
The lockwaitalert value sets the timeout, in seconds, for kcml.native.lock - if $OPEN takes longer than that time to obtain the lock then the kcml.native.lock metric will be sent. The default, if no lockwaitalert value is set, is 2 seconds. The maxtranstime value set the threshold, in seconds, over which the life-time of a transaction will be reported by the kcml.kdb.transtime & kcml.sql.opttranstime metrics. The default value is 2 seconds.

The x509warndays setting sets the number of days before certificate expiry that the kcml.x509.expiry metric will be sent. The default is 30.

By default all performance metrics are not enabled. However performance metrics can be enabled, for all partitions, when $PSTAT is created by specifying them in the [perfmetric] section of msgq.conf:-

# Send performance metrics to myQueue and always enable kcml.session.start and kcml.session.lic
[perfmetric]
queue=myQueue
kcml.session.start=1
kcml.session.lic=1

Access Control

Text-string|YYYY-MM-DDThh:mm:ssZ<crlf>

A SHA-256 message digest signature is then calculated, using a private key, and then appended after being base-64 encoded:-

Text-string|YYYY-MM-DD hh:mm:ss<crlf>
signature=xxxxx...

Where xxxxx... is the base-64 encoded signature.

The public key is then extracted from the private key and then added to the [perfmetric] section of /etc/kcml/msgq.conf:-

# Enforce security for 'KCML_PerfMetric_Set() and 'KCML_PerfMetric_Clear()
[perfmetric]
queue=myQueue
pubkey=zzzzz...

Where zzzzz... is the base-64 encoded public key.
When 'KCML_PerfMetric_Set() & 'KCML_PerfMetric_Clear() are called they inspect the timestamp and check that it is within 5 minutes of the current time. If the timestamp is outside of that margin the functions will fail and return a value of _KCML_PERFMETRIC_TOKENEXPIRED. The default margin can be changed by specifying the tokentimestampmargin value, in seconds, in the [perfmetric] section on /etc/kcml/msgq.conf

# Enforce security for 'KCML_PerfMetric_Set() and 'KCML_PerfMetric_Clear()
# Increase timestamp margin to 10 minutes.
[perfmetric]
queue=myQueue
pubkey=zzzzz...
tokentimestampmargin=600

The signature will then be verified using the public key that was added to /etc/kcml/msgq.conf, if no pubkey value was added to /etc/kcml/msgq.conf then _KCML_PERFMETRIC_NOPUBKEY will be returned. If the signature is valid then the state of the perfmance metric will be changed, othwise a value of _KCML_PERFMETRIC_VERIFYFAILURE will be returned.

The KCML process that calls 'KCML_PerfMetric_Set() & 'KCML_PerfMetric_Clear() should not have access to the private key, ie to avoid the possibility bypassing the security by using self-signed tokens. Typically the token, and its signature, would be constructed on a different machine and then passed to a SOAP server, that verifies the signature using the public key, when it calls 'KCML_PerfMetric_Set() & 'KCML_PerfMetric_Clear().

However on internal development systems such security may not be required and can be disabled by adding the suppressverify key to the [perfmetric] section of /etc/kcml/msgq.conf :-

# Disable security for 'KCML_PerfMetric_Set() and 'KCML_PerfMetric_Clear()
[perfmetric]
queue=myQueue
suppressverify=1

In this case the sToken$ parameter can be omitted or passed an empty string.

Message Format

Messages are plain text and begin with a name of the form kcml.perf.metric. Then a common set of comma-separated key=value pair identifiers are included.

This set of values is also included with application performance metrics sent using 'KCML_PerfMetric_Send().

Each performance metric then appends one or more, comma separated, key=value pairs.
For example, kcml.load.prog

kcml.load.prog,host="centos6.kcml.com",user="fred",pid=6481,uuid="884a1fc0-65f9-4a53-9d8e-875172abf5b6",ts=1488216010824575,exe="kcml",service="MyApp",part=1015,file="/user1/src/myapp/sw/progs/main.src",loadtime=2545

List of Performance Metrics

Below is a list of performance metrics with the common set of key=value pairs omitted for clarity. All time values are in micro-seconds, unless otherwise stated. Hover the mouse pointer over each statistic for a description.
Note that not all constants have unique value as some metrics are enabled in pairs, for example kcml.session.start & kcml.session.end.

The [perfmetric] section supports the following settings:-

Application Performance Metrics

Application code may also be instrumented. As all KCML internal performance metrics use microseconds it is also recommended to do the same. An application's metric name may be any string value except that is must not begin with "kcml".

The example below uses 'KCML_PerfTimer_Start() and 'KCML_PerfTimer_Stop() to measure how long a subroutime took to execute and then sends the statistics to the RabbitMQ server using 'KCML_PerfMetric_Send().

00010 'main()
    : $END
    : DEFSUB 'main()
    : LOCAL DIM rTimes$_kcml_perftimerrec
    : LOCAL DIM nTimerId AS integer
    : 
    : REM Start a performance timer
    : ntimerid = 'KCML_PerfTimer_Start()
    : 
    : REM call the code to be monitored
    : 'doSomeThing()
    : 
    : REM Stop the performance timer
    : 'KCML_PerfTimer_Stop(ntimerid,BYREF rTimes$)
    : REM Report the statistic
    : 'KCML_PerfMetric_Send("","my.app.metric",$PRINTF("elapsed=%d,exectime=%d,usertime=%d,kerneltime=%d",FLD(rTimes$.KCML_PerfTimer_Elapsed),FLD(rTimes$.KCML_PerfTimer_Exec),FLD(rTimes$.KCML_PerfTimer_User),FLD(rTimes$.KCML_PerfTimer_Kernel)))
    : END SUB
    : 
    : REM Fake up application processor and idle time
    : DEFSUB 'doSomeThing()
    : LOCAL DIM i AS integer
    : LOCAL DIM j AS integer
    : LOCAL DIM rc
    : LOCAL DIM a$0
    : 
    : FOR i = 1 TO 1000
    :     REM Fake up execution time
    :     FOR j = 1 TO 1000
    :         REDIM a$ = $UPPER("quick brown fox")
    :     NEXT j
    :     REM Fake up idle time by pausing for 1 millisecond
    :     rc = $IF,1
    : NEXT i
    : END SUB

The final message sent via 'KCML_PerfMetric_Send() is the application's metric name followed by the common set of identifiers and then finally the list of statistics the application has measured.
For example, the above program may report the following to the message queue:-

my.app.metric,host="myserver",user="fred",pid=29583,uuid="e8bf5cba-183f-40c8-9e30-cf5674c9ee3f",ts=1490374670046022,exe="kcml",part=2048,elapsed=2372010,exectime=160416,usertime=163000,kerneltime=19000

ODBC Performance Metrics

The 07.22 version of kiodbc will also produce performance metrics in the same way as KCML. As kiodbc processes tend to be short-lived & they are not interactive there is little opportunity to enable additional metrics on a running process. It may also be desireable to only have kiodbc report certain database metrics such as kcml.kdb.io, as a KCML process may produce too many messages. Additional metrics for kiodbc can be configured by listing them in the [odbc] section of /etc/kcml/msgq.conf :-

# Additional default metrics for kiodbc only
[odbc]
kcml.kdb.io=1
kcml.kdb.fetch=1
kcml.odbc.fetch=1
kcml.odbc.prepare=1