Measuring IBM MQ Distributed API Response Time with Activity Trace

If you have the need to find out the MQ application response time for certain MQ API calls (e.g. MQPUT, MQGET, etc.) on a distributed IBM MQ queue manager, a good option is to use the Application Activity Trace. This post will give an example of how to do this by using the Application Activity Trace and the mqtrcfrmt program (found in the MH06 supportpac) to find the summarized MQ API performance data by application. As a note, this MQI performance data is the “Approximate API call duration, in microseconds, within the queue manager.”, per the QMgrOprDuration documentation in the IBM MQ manual. This example will use the amqsblst sample, as it can pump a lot of messages in a short amount of time.

Step 1: Turn on the Activity Trace

There are several ways to turn on the Activity Trace, but we will use the following runmqsc command:

ALTER QMGR ACTVTRC(ON)

Step 2: Collect your MQ API results

In our case, we will run the amsblst sample and have it PUT 10,000 messages on the queue Q1 located on queue manager QM1.  If your application was already running, turning on the activity trace in step 1 will cause any subsequent API calls to start to be recorded for the activity trace.

> amqsblst QM1 Q1 -W -c 10000

welcome to blast

Blast> successfully opened queue <Q1>

Blast> 100 messages sent

Blast> 200 messages sent

.

.

Blast> 9900 messages sent

Blast> 10000 messages sent

Blast> elapsed time = 14.535552 S

Blast> ended

Blast> 10000 messages have been put

Blast> 0 messages have been got

Step 3: Turn off the Activity Trace

We will use the following runmqsc command to turn off the activity trace:

ALTER QMGR ACTVTRC(OFF)

Step 4: Use amqsact to collect your results in a verbose format

We will use the amqsact sample to collect the activity trace results to a file using the verbose format:

> amqsact -v > amqsact.out

Step 5: Use mqtrcfrmt from the MH06 supportpac to summarize the Activity Trace data

The Activity Trace data can generate a lot of data. We will use the mqtrcfrmt that is in the MH06 supportpac to summarize the data so we can see the average response times for our amqsblst PUTs. The mqtrcfrmt is a Java jar, and it requires a Java 1.8 JRE. I believe all supported IBM MQ versions (v9.0 and higher) come with a Java 1.8 JRE, if you install the java portion in your MQ install. In my case, I was using a MQ 9.2.0.1 queue manager on Linux, and it has a Java 1.8 JRE under /opt/mqm/java/jre64/jre/bin/java.

# Confirmation that this JRE is 1.8

> /opt/mqm/java/jre64/jre/bin/java -version

java version "1.8.0_261"

Java(TM) SE Runtime Environment (build 8.0.6.15 - pxa6480sr6fp15-20200724_01(SR6 FP15))

IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20200724_452227 (JIT enabled, AOT enabled)

OpenJ9   - 4ce4b9d

OMR      - 08b0594

IBM      - 70917a2)

JCL - 20200720_01 based on Oracle jdk8u261-b13

Here is the mqtrcfrmt command to format the amqsact.out file to have the summary report data by connection at the end of the formatted .2 file.

> /opt/mqm/java/jre64/jre/bin/java -jar mqtrcfrmt.jar -t aat -i amqsact.out

mqtrcfrmt version 1.0.10

Endianness was not explicitly set. Defaulting to little endian.

traceType (-t) has been explicitly set to aat.

dumpLinePrefix is hard coded to 0000 for aat

inputFileCharSet (-c) not explicitly set. Defaulting to UTF-8.

pointerLength (-p) not explicitly set. Defaulting to 8.

mqtrcfrmt will now begin formatting 1 trace files.

Formatted trace files will have a suffix of .2 and will be located in /tmp

If I go to the bottom of my amqsact.out.2 formatted file and search up for amqblst, I see the following report for this amqsblst application. Because amqsblst runs under one connection, we find just the one report. However, if your application used multiple connections, you would find a separate report for each connection.

qmgrName('QM1') applName('amqsblst') userId('mqm') pid(11438) channel() connId(31DDB55F01D8F420):

Opr(MQXF_CLOSE) OprCt(1) avgOprDuration(49) ObjType(MQOT_Q) ObjName('Q1') reasonCds=0

Opr(MQXF_CONN) OprCt(1) avgOprDuration(4713) reasonCds=0

Opr(MQXF_DISC) OprCt(1) reasonCds=0

Opr(MQXF_OPEN) OprCt(1) avgOprDuration(4903) ObjType(MQOT_Q) ObjName('Q1') reasonCds=0

Opr(MQXF_PUT) OprCt(10000) avgOprDuration(1235) ObjType(MQOT_Q) ObjName('Q1') Prst(2) msgTotalLength(10240000) reasonCds=0

I see in this application summary report that there were 10,000 PUTs, and the average OprDuration (which is in micrsoseconds) is 0.001235.  Therefore, the PUTs are performing on average at the subsecond millisecond range of 0.001 in the queue manager. As a note, not all operations (e.g. DISC) have a QMgrOprDuration in the activity trace data, but most do. Also, the Activity Trace does need to be at a TraceLevel=MEDIUM in order for there to be this QMgrOpDuration data. However, TraceLevel=MEDIUM (found in the mqat.ini file for your queue manager, which is in the same directory as your qm.ini file) is the default setting for a distributed IBM MQ queue manager, so by default you should get this QMgrOpDuration response time data in the Activity Trace data.