Identifying message latency problems
You can use MainView for MQ to identify which queues are having latency problems.
A high Message latency for a given queue can be a normal occurrence for some queues and applications, but signal a problem with other queues. Problems can occur if messages are not being processed in a timely manner. With MainView for MQ, alarms can be set on various fields to identify message problems. This section steps through a sample scenario for identifying a queue that is having Message latency problems.
If an application is having problems processing messages in a timely manner, start by looking at the queue performance data for queues that the application is processing.
To determine if an application is having message processing problems
To see a list of all of the queues and their performance data, access the QP view.The following information is displayed:
W1 =QP================GRT2=====*========DDMMMYYYY==14:32:37====MVMQS====D===16
C Queue Current Get Put Open Close
- Name Depth Rate Rate Count Count
bbs.COMMAND.REPLY.GRT2 2 0.42 0.48 11 11
wasq1 1 0.00 0.00 0 0
AMQ.rkellogg_63181.PUB 351 0.00 0.00 0 0
AMQ.JOPRICE_43181.PUB 253 0.00 0.00 0 0
BBSMVMQS.REPLY.GRT2 4 23.13 23.14 95 89
CSQ4SAMP.B2.C.RESPONSE 1 0.00 0.00 0 0
GRT2.DEAD.QUEUE 414 0.00 0.00 0 0
MCB.QUEUE 0 0.15 0.14 7 7
SAVEQMGR.REPLY.QUEUE 4 0.00 0.00 0 0
SYSBMC.A64E.EVENTS 26 0.00 0.00 0 0For this example, you determine that the MQAPPL1 application is having problems, and you know that MQAPPL1 is servicing the queue named MCB.QUEUE.
To view detailed performance data for the queue, click the MCB.QUEUE queue name to access the QPD view.The following information is displayed:
W1 =QP=======QPD======GRT2=====*========DDMMMYYYY==14:32:00====MVMQS====D====1
Queue............ MCB.QUEUE
Queue Manager.... GRT2
Current Depth.... 0
Max Depth Ever... 12
Min/Max Messages.
Longest Get..... 4096
Longest Put..... 4096
Shortest Get.... 16
Shortest Put.... 16
Interval Session
API Counts.......
MQOPEN.......... 7 0.08 14 0.15
MQPUT........... 18 0.19 36 0.39
MQPUT1.......... 0 0.00 0 0.00
MQGET........... 19 0.20 38 0.41
MQCLOSE......... 7 0.08 14 0.15
Failed MQOPEN... 0 0.00 0 0.00
Failed MQPUT.... 0 0.00 0 0.00
Failed MQPUT1... 0 0.00 0 0.00
Failed MQGET.... 0 0.00 0 0.00
Failed MQCLOSE.. 0 0.00 0 0.00
Expired Msgs.... 0 0.00 0 0.00
MQGET w rc=0..... 19 38
MQGET w rc=1..... 0 0
Bytes............
Max Depth....... 0 0
Avg Latency..... 2.68 2.68
MQPUT Msg Bytes. 45664 491.27 45952 494.37
MQPUT1 Msg Bytes 0 0.00 0 0.00
MQGET Msg Bytes. 45664 491.27 50048 538.44You can see that the Average Latency values for this queue are high (2.68).
To see how many get latencies are high for MCB.QUEUE, click the Avg Latency field to access the QPGLD view.The following information is displayed:
W1 =QPGLD=============GRT2=====*========DDMMMYYYY==14:31:06====MVMQS====D====1
Get Latency Info........
Queue.................. MCB.QUEUE
Queue Manager.......... GRT2
% of % of
Get latency Distribution Session Total Interval Total
Period 1............... 0.05 0 0.00 0 0.00
Period 2............... 0.25 12 31.58 6 31.58
Period 3............... 0.50 24 63.16 12 63.16
Period 4............... 1.00 0 0.00 0 0.00
Period 5............... 3600.00 2 5.26 1 5.26
Period 6............... No limit 0 0.00 0 0.00
Average Access Times.... 2.679616 2.679616This view shows the Get latency distributions for the MCB.QUEUE queue. Two high latencies appear in the Period 5 bucket.
Now that you know that this problem a high latency problem, you will want to view and search for all trace entries for MCB.QUEUE.
To retrieve MQ API trace records for previous trace periods, the Next Generation Logger (NGL) must be configured. MQ API trace records are written to NGL when the current internal trace buffers fill up in the data space. If NGL is not configured, MQ API trace records are lost when the internal trace buffers fill up and are reused.
For information about the EXITOPT parameters that are required to use NGL, see Setting-up-EXITOPT-DD-parameters. For complete information about NGL, see the BMC Infrastructure Components Administration Guide
- On the EZMQS Easy menu, click WS MQ API Trace.For this scenario, NGL is configured, and an MQI Trace Search dialog is displayed. This search dialog allows filters to be set for searching MQ API trace records. This dialog is only displayed when you hyperlink from the EZMQS menu to the MQITRACE view and NGL is configured.
Filter the search for MQI API trace records by entering the queue name, MCB.QUEUE, and the search time (start time of today, with no end time).The following figure shows the MQI Trace Search dialog with search filters entered:
DDMMMYYYY 13:07:18 ------ MainView WINDOW INTERFACE (V5.0.05) ---------------
MQI Trace Search
COMMAND ===> SCROLL ===> CSR
Job Name
Application Name
Queue Name MCB.QUEUE
Resolved or Named R (R or N)
Search Start Time 00:00:00.00 (hh:mm:ss.tt)
Search Start Date 2006/11/13 (yyyy/mm/dd)
Search End Time (hh:mm:ss.tt)
Search End Date (yyyy/mm/dd)
GMT Time N (Y or N)
Maximum Records 5000
END to process request
CANcel to exit without processing
Reset to reset to initial data
Help to view related helpPress END to start the search.By entering the search criteria, MainView for MQ searches all MQ API trace records in the data space (the current real-time records) and the NGL files. All records that match (up to the Maximum Records value specified) are displayed on the MQITRACE view. In this case, all MQ API trace records that match the queue name MCB.QUEUE and have a date of 11/13/2006 are returned, as shown in the following figure:
W1 =MQITRACE==========GRT2=====*========DDMMMYYYY==14:35:26====MVMQS====D==408
CMD Time Function Application Object
--- Recorded ~ Name Name
14:34:23.81 MQClose MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQGet MQAPPL1 MCB.QUEUE
14:34:23.81 MQOpen MQAPPL1 MCB.QUEUE
14:34:21.98 MQClose MQAPPL1 MCB.QUEUEThe search returned 408 MQ API trace records that matched MCB.QUEUE.
Scroll to the right on the trace records and look for high latency values or sort by Message latency value.
For this example, the threshold is set to ten seconds, so any Get latency values over 10 seconds are highlighted in yellow.
The following information is displayed:
+W1=MQITRACE==========GRT2=====*========DDMMMYYYY==14:35:26====MVMQS====D==408
CMD Time Time (STCK) Message taskno Message
--- Recorded Recorded Latency number ID
14:29:24.65 BFB38B93299FE3C9 46.078750 00000000 C3E2D84
14:28:02.39 BFB38B44B54E968C 40.943385 00000000 C3E2D84
14:34:15.96 BFB38CA8F87F1006 26.881649 00000000 C3E2D84
13:14:25.28 BFB37AD039BCFD49 24.355135 00000000 C3E2D84
14:21:27.83 BFB389CC6E991E89 21.289185 00000000 C3E2D84
14:22:06.14 BFB389F0F6C239C4 3.915635 00000000 C3E2D84
14:21:51.49 BFB389E2FD3AE3EC 2.022078 00000000 C3E2D84
14:21:51.49 BFB389E2FD3362AC 2.021958 00000000 C3E2D84
14:21:51.49 BFB389E2FD2AEB2C 2.021822 00000000 C3E2D84
14:21:51.49 BFB389E2FCFC5EAB 2.021077 00000000 C3E2D84An MQGET has a Message latency of over 46.07 seconds.
To get more information about the specific MQGET call, click the latency value (46.078750).The MQITD view is displayed with the following information:
>W1 =MQITRA=MQITD====GRT2=====*========DDMMMYYYY==14:35:26====MVMQS====D====1
Function........ MQGet Time Recorded. 14:29:24.65
ASID............ 0036 QMGR.......... GRT2
TCB Address..... 006D0E88 Object name... MCB.QUEUE
EB Address...... 0D261638 Appl Name..... MQAPPL1
Platform........ MVS Obj Type...... Queue
PlatName........ x &. Sub Type...... Local
Rectype......... Res QMGR...... GRT2
Job Name........ MQAPPL1 Res Name...... MCB.QUEUE
User ID......... ROHMCB7 Message ID.... CSQ GRT2 x- »Å..ä
Appl Type....... MVS C3E2D840C7D9E3F2404040404
Msg Size........ 4096 Correlation ID
Return.......... 0 0000000000000000000000000
Reason (Decimal) 0 Reason........ MQFB_NONE
CPU Time........ 0.000129 CICS Tran ID.. N/A
Elapsed time.... 0.000135 CICS Taskno... N/A
Message Latency. 46.078750 Open Options.. N/A
Message Priority 0 Get Options... No Syncpoint, Accept Truca
Expired Messages 0 Put Options... N/A
Close Options. N/A
<show message descriptor>The MQITD view provides more information about the specific MQGET API call on which the high Message latency occurred.
Click the <Show Message Descriptor> field to see more detailed information to help you identify the high latency problem.The MQMD view is displayed with the following information:
>W1=MQMD==============GRT2=====*========DDMMMYYYY==14:41:56====MVMQS====D====1
Format.............. MQSTR Queue Manager...... GRT2
Type................ Datagram Queue.............. MCB.QUEUE
Report Options...... Reply to Queue.....
Exception......... No Queue Manager.... GRT2
Expiration........ No Queue............
Arrival Confirm... No
Delivery Confirm.. No Queuing Application
Message ID........ New MsgId Type............. MVS
Correlation ID.... Copy MsgId Name............. MQAPPL1
Priority............ 0 Put Date........... 13NOV2006
Expiry Time......... 429496576.0 Put Time........... 22:28:38.58
Backout Count....... 0
Length.............. 4096 Feedback Code......
Feedback Symbol.... MQFB_NONE
Data Encoding....... Native
Coded Char Set ID... 000001F4 Message Id......... C3E2D840C7D9E3F2404
Persistence......... No Correlation Id..... 0000000000000000000
User Id............ ROHMCB7
Segmentation Options
Allowed........... No Appl Id Data.......
Message Segment... No Appl Origin Data...
Last Segment...... No
Message in Group.. No Segmentation.......
Last Msg in Group. No Group Id......... 0000000000000000000
Msg Seq Number...
Offset...........
Original Length..