MQ

This is the first blog in a short series that aims to help understand:

• The costs reported by MQ accounting trace on z/OS, focusing on what options are available.
• When to use any particular level of accounting trace.
• Why you might see different costs reported for the same workload depending on the trace option chosen.
• Worked examples of the costs reported for a locally attached workload.

 

In the second blog, we will look at extending the example to include client applications that interact with the queue manager via the channel initiator.

Introduction

MQ Accounting data gives an indication of the cost of the MQ APIs being used within your applications.

 

MQ for z/OS offers a number of different classes of accounting trace:

• 1 – Processor time spent processing all MQI calls and a count of MQPUT, MQPUT1 and MQGET calls, also referred to as “basic” accounting trace.
• 3 – Enhanced accounting data for each task at thread and queue level.
• 4 – Channel accounting data.

 

For detailed analysis of application interaction with MQ, we tend to use class(3) accounting but recognize that there are some additional overheads associated with this enhanced accounting data and it may be more suitable to run with class(1) accounting generally and enable class(3) accounting for short periods.

 

Class(1) accounting data gives the task level cost of the MQ APIs used plus a count of the number of MQPUT, MQPUT1 and MQGET APIs. This information is produced when a named task disconnects from IBM MQ, and so the information contained within the record might cover many hours.

 

Class(3) accounting data gives a task-oriented view of the cost of the interaction between application (or channel initiator) and the MQ queue manager. Since the data gathering for the accounting trace occurs closer to the queue manager than class(1) accounting, the values are typically equal to or less than the class(1) costs reported.

 

With the more granular approach to data gathering of this enhanced data, there is additional cost from data collection. This additional cost varies based on workload type and production method, and is often marginal if the workload is primarily long-lived tasks, such as channels, long running transaction or processes, and using log streams for SMF data. At the opposite end of the cost range is when the work is primarily short-lived high-volume transactions and traditional datasets are used for the SMF data.

 

With  enhanced accounting enabled, all MQ APIs invoked are reported. This additional API information means that it is possible to begin to determine inefficiencies in the MQ usage, for example MQPUT1 many times to the same queue, rather than MQOPEN, PUT (many), MQCLOSE.

Class(4) accounting data gives similar information as can be reviewed with the "DISPLAY CHSTATUS" command, such as achieved batch sizes, data compression rate, time spent in exit routines.

Class(4) statistics data gives the channel initiators’ view of the cost of remote partners, whether client applications or remote queue managers, on the tasks running within the channel initiator address space.

 

The MQ accounting data can be used in conjunction with the RMF Workload data to determine the cost of MQ interactions, but will not include MQ queue manager service task costs such as logging.

What differentiates class(1) and class(3) accounting data?

Basic accounting was designed and built for charge back purposes much earlier than the expansion of MQ verbs in MQ version 7, when the more typical model was long running tasks and smaller messages. The enhanced accounting was designed and built for the detail needed when looking into transaction and queue manager performance and problem determination requirements.

 

Basic accounting such as that reported by class(1) accounting is run at a task level but only gathers a small amount of data, including the number of MQPUT, MQPUT1 and MQGETs, plus the total amount of CPU time used when calling all MQ APIs.

 

When gathering class(1) data and formatting using the MQSMF program available as part of “MP1B: IBM MQ – Interpreting accounting and statistics data, and other utilities”,  you may see output similar to:

 

z/OS:MVAA  MQ QMGR:VTS1  Time: 2020063 15:43:19.07                                            QWHS: Job IYAAVC01,  Job userid PERFTASK,  Tran userid PERFTASK,              Conn type CICS   Thread 22EF52A0 CBL4 QWHC: Accounting token 9UNKNOWNIYAAVC01     k,  Network identifier IYAAVC01P                  QMAC: CPU us 0000000058  0-99       100-999     1000-9999         >9999                               MQPUT             0             0             0             0                                 MQGET             0             0             1             0

 

In this example, the application is a CICS transaction that is issuing MQOPEN, MQGET and MQCLOSE.

 

The basic accounting data accumulates the CPU used for all 3 of these APIs but only reports that a single MQGET was completed and that get was of a message of between 1000 to 9999 bytes.

 

Enhanced accounting as reported by class(3) accounting trace once more gathers data at a task level but offers significantly more data, as demonstrated by the contents of the MQSMF program’s TASK report:

MVAA,VTS1,2020/03/03,15:43:19,VRM:915,                                    VTS1 CICS IYAAVC01 opid:PERFTASK userid:PERFTASK Tran:CBL4 task:0001555c  Start time Mar  3 15:42:55 2020 Started in a different time interval      Interval   Mar  3 15:42:55 2020 - Mar  3 15:42:55 2020 : 0.000147 seconds Other reqs : Count                 1                                      Other reqs : Avg elapsed time      0 uS                                   Other reqs : Avg CPU               0 uS                                    Other reqs : Total ET              0.000000 Seconds                       Other reqs : Total CPU             0.000000 Seconds                       Commit count                       1                                      Commit avg elapsed time           28 uS                                   Commit avg CPU time                5 uS                                   Backout count                      1                                      Backout avg elapsed time           2 uS                                    Backout avg CPU time               2 uS                                   Suspend count                      1                                      Suspend avg elapsed time          23 uS                                   Total suspend time                 0.000023 Seconds                       Pages old                          4                                      Wait for buffer pool latch         0.000000 Seconds                       Held BP Latch                      0.000000 Seconds                       Open name                                  LIXC01                         Queue type:  QLocal                        LIXC01                          Queue indexed by CORREL_ID                 LIXC01                         First opened    Mar  3 15:42:55 2020       LIXC01                         Last closed     Mar  3 15:42:55 2020       LIXC01                         Page set ID                        1       LIXC01                         Buffer pool                        1       LIXC01                         Current opens                      0       LIXC01                         Total requests                     3       LIXC01                         Open count                         1       LIXC01                         Open avg elapsed time             13 uS    LIXC01                         Open avg CPU time                 11 uS    LIXC01                         Close count                        1       LIXC01                         Close avg elapsed time             2 uS    LIXC01                         Close avg CPU time                 2 uS    LIXC01                         Get count                          1       LIXC01                         Get avg elapsed time              21 uS    LIXC01                         Get avg CPU time                  18 uS    LIXC01                         Get TOQ average                 1939 uS    LIXC01                          Get TOQ maximum                 1939 uS    LIXC01                         Get TOQ minimum                 1939 uS    LIXC01                         Get valid count                    1       LIXC01                         Get valid destructive              1       LIXC01                         Get size maximum                2048 bytes LIXC01                         Get size minimum                2048 bytes LIXC01                         Get size average                2048 bytes LIXC01                         Get dest-next                      1       LIXC01                         Get not persistent count           1       LIXC01                         Curdepth maximum                   0       LIXC01                         Total queue elapsed time          37 uS    LIXC01                          Total queue CPU used              31 uS    LIXC01                         Grand total CPU time        0.000039 S     C,CBL4,"IYAAVC01",             Grand Elapsed time          0.000068 S     C,CBL4,"IYAAVC01",

 

In this example, we once more see the MQGET of a 2KB non-persistent message.

 

We also see that the queue “LIXC01” has been opened and closed once, as well as the application having performed an MQCMIT as part of the explicit EXEC CICS SYNCPOINT.

 

With the enhanced accounting data, we can see a number of interesting times including:

• Grand total CPU time (MQ): 39 microseconds
• Grand elapsed time (MQ): 68 microseconds
• Interval time (for the task): 147 microseconds

This means that the CICS transaction ran for approximately 147 microseconds, of which 68 microseconds was in MQ APIs and those MQ APIs cost 39 microseconds.

 

One final observation to emphasize is the CPU cost for these 2 transactions is different:

Basic accounting:                    58 microseconds
Enhanced accounting:            39 microseconds

  

Why does basic accounting sometimes reports higher cost than enhanced accounting?

This is most simply demonstrated when we look at the call stack into the queue manager for an MQPUT.

Application calls MQPUT
CSQMCPRH	Accounting class(1) starts accumulating time
CSQMPRH2
CSQ7COLL	Accounting class(3) starts accumulating time
CSQMPUT0
..
CSQ7COLL	Accounting class(3) stops accumulating time
CSQMPRH2
CSQMCPRH	Accounting class(1) stops accumulating time
Application checks MQPUT RC

 

The class(3) accounting MQ API cost measures the CPU used by the task from part-way through the first call to CSQ7COLL until part-way through the second call to CSQ7COLL.

The class(3) accounting cost is a subset of the class(1) accounting cost, which in turn is a subset of the actual cost of the MQAPI request by the calling application.

 

To put the costs in a diagram:

Notes on diagram:

• The RMF workload, reporting by classes "Application A", “Application B” and "QMGR" would show the CPU used by address space.
• The class(1) data would show the CPU time spent in all MQ API calls plus a count of the number of MQPUT, MQPUT1 and MQGET invoked. The API cost will be formed primarily from the application address space costs and partly (but less so) from the QMGR address space costs.
  • We are also aware that class(1) accounting data can be inaccurate in a CICS environment depending on workload volumes.
• The class(3) data would show the CPU used by all the APIs for the application - once again primarily from the application address space and partially from the QMGR address space.

 

What this means is that the queue manager costs are generally quite low, except when the queue manager is performing various internal tasks, such as logging-related tasks such as those required for persistent messaging and the offload of full active logs to archives, or writing to large shared queue messages to Db2[1].

Worked example of non-persistent costs

In this example we show the costs as reported by RMF’s workload report and compare this with the contents of the enhanced accounting data i.e. class(3) accounting.

 

This particular workload uses a simple request/reply workload using 64KB non-persistent messages where the server task issues MQGET, MQPUT and MQCMIT to ensure the work is completed in a transaction i.e.

 

The applications are long running batch tasks, which open the queues once, put and get many messages and close the queues once. For the purposes of this document, the MQOPEN and MQCLOSE costs are negligible and can be ignored.

 

The applications are designed to only drive MQ workload – they aren’t performing extraneous tasks, for example complex calculations, intensive file I/O or database queries, and yet as we demonstrate below, the cost of the transaction is largely in the applications.

Who gets charged for the workload according to the RMF Workload report?

 Reviewing the RMF workload report for this measurement suggests that the CPU cost is primarily in the requester and server address spaces e.g.

 

Report Class	CPU microseconds / transaction	% of total cost
MQ	6.4	5.9
REQSTR	47.9	43.9
SVR	54.7	50.2
Total	109.0	100

 

What does the enhanced accounting data show in this example?

 We have extracted the class(3) data and formatted using MQSMF[2], and then subsequently summarized the data in the TASK report such that all requester tasks are treated as one, and similarly treating all server tasks as one. From this view we can calculate the average MQ API costs for the workload by task type.

 

Requester task:

• MQPUT is costing 21 microseconds on average.
• MQGET costing 9 microseconds, but for each message put, the task is performing 2 MQGETs – as the application was ready for the reply message before the reply was actually available. This means the MQGET cost for a successful get is effectively 18 microseconds.

 

In this case, the requester task has 39 microseconds of MQ API costs out of the total 47.9 for a transaction, or 81% of the total cost of the application.

 

Server task:

• MQGET costing 10 microseconds, but for each MQGET that is successful, the workload is averaging 1.82 MQGETs attempted. This means that the MQGET cost for a successful get is 18.2 microseconds.
• MQPUT costing 23 microseconds.
• MQCMIT costs 3 microseconds.

 

In this case, the server task has 44.2 microseconds of MQ API costs out of the total 54.7 for a transaction, or 80.8% of the total cost of the application.

 

In this non-persistent example, we see that 83.2 of 109 CPU microseconds from the average transaction cost is reported by the enhanced accounting trace data, with an additional 6.4 CPU microseconds in the MQ MSTR address space that we have determined from the RMF workload report.

Why is the queue manager cost such a low proportion of the total cost?

 The MQ API cost is largely charged to the application address space in a non-persistent workload as it is run on the applications’ TCB.

 

Persistent messages are slightly different as the logging of the data to MQ’s active logs is performed on a queue manager SRB, and therefore is charged to the queue manager address space.

Worked example of persistent costs

 In this example we show the costs as reported by RMF’s workload report and compare this with the contents of the enhanced accounting data when the workload uses 64KB persistent messages.

 

Who gets charged for the workload according to the RMF Workload report?

Reviewing the RMF workload report for this measurement suggests that the CPU cost increases significantly in the MQ MSTR address space as well as seeing an increase in the application address spaces, e.g. 

Report Class	CPU microseconds / transaction	% of total cost
MQ	144.8	43.2
REQSTR	101.2	30.2
SVR	88.9	26.5
Total	334.9	100

 

In this example the requester does MQPUT, MQCMIT, MQGET, MQCMIT whilst the server does MQGET, MQPUT and MQCMIT.

 

What does the CLASS(3) Accounting data show in this example?

 Extracting the class(3) data and formatting using MQSMF, and then summarizing the data in the TASK report such that all requester tasks are treated as one, and similarly treating all server tasks as one. From this view we can calculate MQ API costs for the workload by task type.

 

Requester task:

• MQPUT is costing 53 microseconds on average.
• MQGET costing 12 microseconds, but for each message put, the task is performing 2 MQGETs – as the application was ready for the reply message before the reply was actually available. This means the MQGET cost for a successful get is 24 microseconds.
• MQCMIT costs 3 microseconds, and since there are 2 commits per transaction, this means a cost of 6 microseconds per transaction.

 

In this persistent workload, the requester task has 83 microseconds of MQ API costs out of the total 101.2 for a transaction, or 82% of the application cost.

 

Server task:

• MQGET costing 24 microseconds, and each MQGET is successful.
• MQPUT costing 51 microseconds.
• MQCMIT costs 3 microseconds.

 

In this case, the server task has 78 microseconds of MQ API costs out of the total 88.9 for a transaction, or 87.7% of the application cost.

 

MQ MSTR address space:

In the persistent workload measurement, we see a significant amount more CPU charged to the queue manager – 144.8 CPU microseconds per transaction, up from 6.4 microseconds per transaction in the non-persistent measurement.

 

Of this 144.8 CPU microseconds per transaction:

• 80.9 microseconds is queue manager SRB, primarily in active log costs.
• 63.9 microseconds is queue manager TCB, primarily in archive log costs.

 

In this persistent example, we see that 161 of the 334.9 CPU microseconds average transaction cost is reported by the enhanced accounting trace data, with an additional 144.8 CPU microseconds in the MQ MSTR address space.

Summary

Performance report MP16 offers guidance on the cost of running with each of these accounting trace options – generally basic accounting and channel initiator accounting trace options costs are low and it is advisable to run with these by default and review them periodically.

 

Depending on your environment, you may be able to run with enhanced accounting all of the time or at least periodically to be able to gather data from when workload is running well. This provides a set of baseline data to compare with, should performance appear to change over time.

 

For complex workloads, basic and channel initiator accounting data may not provide sufficient granularity of the data particularly when the application is using multiple queues or mixed message sizes or some of the newer MQ APIs – which is another reason why we would enable class(3) enhanced accounting periodically to allow comparisons with earlier data running similar workloads.

 

To recap:

• Class(1) gives a high level view for all tasks that have disconnected in the SMF interval but only provides a guide to the total MQ API cost plus a summary of MQPUT, MQPUT1 and MQGET API calls. As the class(1) data is accumulated closer to the application the class(1) reported costs may be higher than the class(3) costs, but the cost of data collection is much less as the reporting is only at end of task and there is significantly less data recorded.

 

• Class(3) gives the most granular breakdown of MQ costs by task, but may be too costly to run enabled at all times. Long running tasks that span multiple SMF intervals will receive multiple SMF 116 records. If running with enhanced accounting for extended periods, it may be advisable to use SMF log streams.

 

• Class(4) accounting data gives a view of the channel, such as how much data has flowed over the channel, whether it was persistent or non-persistent data, number of batches - largely it is a record of the sort of data that can be gathered from periodic "DISPLAY CHSTATUS" commands. The accounting data does report the dispatcher task used by the channel but does not report costs of the interactions.

• Class(4) statistics gives a high level view across the channel initiator, and can be used to determine whether you have sufficient tasks. If you are only running a small set of workloads, you may be able to correlate the cost of the adaptor task with the MQ API and determine relationships between the number of dispatcher and SSL calls per API, but as soon as you add complexity to your measured workloads, it becomes difficult to show the correlation between channel initiator task and MQ API cost.

 

Useful links:

MP16 – Guidance on the cost of accounting trace for classes 1, 3 and 4.

MP1B – Interpreting accounting and statistics data, including program MQSMF.

MQSMFCSV – Basic formatter for MQ’s SMF records to assist with importing to spreadsheets and databases.

 

[1] Writing to SMDS is charged to the application as it does not require the same task switch as write to Db2

[2] From Performance SupportPac MP1B.