How long is that MQ call taking?

David Ware |May 14 2015 Updated

You may be aware of MQ's application activity trace feature on the distributed platforms. This allows you to track each individual MQI operation performed by specific applications, showing you lots of really useful information on what an application is actually doing. That's not new, we've had that since MQ 7.1 and you can read about using it here. However, in MQ V8.0.0.2 we added another small piece of information that you should hopefully find useful, it's the number of microseconds actually being spent inside the MQI operation within the queue manager, not just the time that the operation occurred. This is something that will help you to track down those performance issues, often where the finger is being pointed at the MQ system but you don't have the information available to allow you to narrow it down to MQ or the application itself.

The easiest way to view activity trace data is by using the amqsact sample that we ship with the product. This has been updated to display the operation times if you run it in verbose (-v) mode. If you use this you'll see the following kind of output, here's an example MQPUT...

MQI Operation: 0
  Operation Id: MQXF_PUT
  ApplicationTid: 1
  OperationDate: '2015-05-13'
  OperationTime: '09:08:09'
  High Res Time: 1431504489490677
  QMgr Operation Duration: 124
  Completion Code: MQCC_OK
  Reason Code: 0
  Hobj: 2
  Put Options: 8260
  Msg length: 6
  Known_dest_count: 1
  Unknown_dest_count: 0
  Invalid_dest_count: 0
  Object_type: MQOT_Q
  Object_name: 'QUEUE1'
  Object_Q_mgr_name: ''
  Resolved_Q_Name: 'QUEUE1'
  Resolved_Q_mgr: 'QMGR1'
  Resolved_local_Q_name: 'QUEUE1'
  Resolved_local_Q_mgr: 'QMGR1'
  Resolved_type: MQOT_Q
  Report Options: 0
  Msg_type: MQMT_DATAGRAM
  Expiry: -1
  Format_name: 'MQSTR'
  Priority: -1
  Persistence: 2
  Msg_id:
  00000000:  414D 5120 514D 4752 3120 2020 2020 2020  'AMQ.QMGR1.......'
  00000010:  1078 4355 2000 5C02                      '.xCU..\.        '
  Correl_id:
  00000000:  0000 0000 0000 0000 0000 0000 0000 0000  '................'
  00000010:  0000 0000 0000 0000                      '........        '
  Reply_to_Q : ''
  Reply_to_Q_Mgr: ''
  Coded_char_set_id: 0
  Encoding: 546
  Put_date: '20150513'
  Put_time: '08080948'

As you can see in bold above, the number of microseconds taken from the point that the MQPUT was issued on the queue manager to the time that it completed was 124. So if you had activity trace of an application with successive MQI operations that were spaced far apart (judged from the "operation time" or the "high res time" of each operation) but the "QMgr operation durations" were short in comparison it would imply that the cost was either in the application itself, or if they were connecting as clients, perhaps the network layer.

Often when you're looking into these types of problem every little piece of diagnostics helps, hopefully that's the case here.

(For those of you interested, MQIAMO64_QMGR_OP_DURATION is the new parameter you'll see in the generated activity trace PCF data)