Processing Activity Trace PCF messages with Java

This post covers some of the things I found about extending my java program for processing PCF, to cover activity trace 

Operation date has an inconsistent format

The field with MQCACF_OPERATION_DATE  is a field with format SimpleDateFormat(“yyyy-MM-dd” but is a 12 byte field (instead of the 10 you  might expect), and is padded with nulls instead of blanks.  You need to do date = …getStringParameterValue(MQConstants.MQCACF_OPERATION_DATE).substring(0, 10) to  capture the key data.

 

MQIACF_APPL_FUNCTION_TYPE.

This maps to fields MQFUN_TYPE_* with values like MQFUN_TYPE_UNKNOWN, MQFUN_TYPE_USERDEF, MQFUN_TYPE_JVM.   I got Unknown, and do not know what this means.  I think they are connected to the iSeries.

Using the high resolution timer, with microsecond precision.

Puts and gets have a high precision time value. The field MQIAMO64_HIGHRES_TIME gives a microsecond level precision of the time of the time.

To process these values I used

long milliseconds = (long) p.getValue()/1000;
long microseconds = (long ) p.getValue()%1000000;
Calendar cal = Calendar.getInstance();
cal.setTimeInMillis(milliseconds);
Date dateTimeVal = cal.getTime(); 
SimpleDateFormat sdfFormat = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss", Locale.ENGLISH);
System.out.println(""High res timer:" + sdfFormat.format(dateTimeVal 
                                      + "." 
                                      + String.format("%06d", microseconds)  // add microseconds
                                      +"Z") ;

You can use the micro seconds value when doing calculations such as duration between operations.

You get the high resolution timer when doing MQGET, MQPUT, MQPUT1, for the other calls, such as MQOPEN, MQCLOSE, MQCMIT you only get the timer from the “Operation_Time” file for example 18:09:34.
It is not easy to find where your application is spending its time.

For example

MQ Verb	OperationTime	OperationDuration micro seconds	Hi res timer
MQOPEN	18:09:34	56
MQPUT	18:09:34	66	18:09:34.747837
MQCMIT	18:09:34	12
MQGET	18:09:34	60	18:09:34.754299
MQCLOSE	18:09:34	54

This application was doing just MQ verbs. The time between the start of the get and the start of the put 6462 micro seconds.  The put took 66 microseconds, and the commit took 12 microseconds, so there was 6384 microseconds unaccounted for.    This reported duration is at the queue manager level.   There will be elapsed time from issuing the request to get into the queue manager, and back out again.

I put a microsecond timer in my client program to time the MQ requests.   After the MQOPEN, the first MQGET took 2800 microseconds, the second MQGET took 500 microseconds.

There is a big difference in the time as reported by the queue manager, and the time as seen by the application,

• Work has to be done from the API request to be able to issue the network request.
• The request has to flow over the network
• The queue manager has code to catch the network request and issue it to the queue manager
• there is the duration of the request – as seen by the accounting trace
• The reply has to be transformed to a network request
• The reply has to flow over the network
• The reply has to be caught and returned to the application.

If the application was using local bindings it would be quicker, as there would be no network component.

The timer code was

long start = System.nanoTime();
queue.get(msg, gmo);
long duration_in_microseconds = (System.nanoTime() – start) /1000;

Note: the machine may not be able to provide a timer accurate at the nanosecond level.

Embedded structures

Requests for get have embedded structures for MQMD (type MQBACF_MQMD_STRUCT  -7028) and GMO (MQBACF_MQGMO_STRUCT – 7027).
Requests for put have embedded structure for PMO( MQBACF_MQPMO_STRUCT – 7029).

The parameter types are the values for MQ CallBack, and have been reused.

The data is a byte string (MQCFBS) .  I could not find how to easily extract the fields from these structures and display them with having to construct each field myself.   The integer fields can be in bigendian or little endian.  The version field for me was “01000000”  or “02000000” which little endian.  If it was big endian the value would have been “0000001”

I had to write some methods to chomp my way along the string to produce the fields.  I could not find a way of passing the string to a  method and get the fields back.

I created a method for longs, strings, bytes, byte.  I found it easiest to use the get StringValue for the structure.    This gives it to you in a hexadecimal string.   You need to do additional processing for example convert from hex to a String,  convert the string to an integer using base 16.   Byte arrays could be used unchanged.