zOSMON as a feature of zVPS provides real time information, daily reporting, and long term trend capabilities. This page is to provide direction on how to use zOSMON to anlayze CICS transaction response times.
Response time reporting is done at several levels. One measure is total transactions for the CICS region. Another method is reporting by transaction names. For response time, we evaluate the terminated transactions. There is another class of transactions, the long term, or "inflight". Though these do not have a response time, their performance may be critical, and the resources consumed by inflight transactions may impact others or be impacted by others.
Because the overhead of the zVPS analysis is so extremely low, it is safe to monitor performance continously. The concept only monitoring when there is a problem implies diagnostics, where as if one always captures the data, any problem can be diagnosed from existing data rather than having to start a diagnostics tool and hope the problem re-occurs. zVPS focuses on management and ensuring all data is available for performance diagnostics, capacity planning and other parts of performance management such as operational alerts.
zVPS includes a Full Performance Database meaning that all data is captured for long term or post process analysis. The PDB is accessable real time through zVIEW and zMON, or as a batch process using zMAP.
zOSMON provides several CICS reports breaking down the different components of reponse time. Starting at a high level, the following is included on zoscix2/3/4. Response time has two major components:
Dispatch time includes CPU time and for each transaction type CPU time should be close to static for a transaction ID. Dispatch time also includes time to load the program, "PC Load" time. If programs are pre-loaded, this should be zero.
High level gross response time breakout is found on ESACIX2. Response time is broken up into dispatch time and suspend time. Dispatch time includes CPU time, and ZIP time. Suspend time has many components. In the following case, showing total terminated transactions for 3 different regions, V62C show much higher response time and that shows up in both suspend time and dispatch time. Plotting response time over long periods will be important to know what is normal and what is acceptable.
Report: ZOSCIX2 z/OS Region Transaction Analysis Monitor initialized: 10/20/20 at 17:56:00 on Z15S serial 0E0F78 ---------------------------------------------------------------- Time/<-Response Time-> SYSID/ APPLID Group Count Total Susp Disp CPU DISP ZIP Time Resp Time Time Time Wait CPU ---- ------- -------- ----- ----- ----- ----- ----- ----- --- 10/20/20 17:56:00 - 17:57:00 V24A C24ASTND Totals 688 0.016 0.006 0.010 0.007 0.001 0 V24B C24BSTND Totals 992 0.025 0.014 0.011 0.008 0.001 0 V62C CICSJA69 Totals 440 0.618 0.510 0.108 0.021 0 0
Suspend time includes dispatch delay as well as other components. At a high level, dispatch delay includes time for first dispatch, I/O wait and a large "other" bucket. There are always unaccounted time as well.
Report: ZOSCIX2 z/OS Regi Velocity Software Corporate ZMAP 5.1. Monitor initialized: 10/20/20 ------------------------------------------------------------------------- Time/<-Total-> <------Dispatch Delays--------> SYSID/ APPLID Group Count <--CPU--> <-------milliseconds----------> Time Secs Pct 1StDisp I/O Wait Other Unknown ---- ------- -------- ----- ---- ---- ------- -------- ----- ------- 10/20/20 17:56:00 - 17:57:00 V24A C24ASTND Totals 688 4.86 8.11 0.005 0.001 0.000 0 V24B C24BSTND Totals 992 8.27 . 0.012 0.000 0.001 0 V62C CICSJA69 Totals 440 9.26 . 0.510 0 0 0
Suspend time is the total time the transaction was suspended and includes
Part of performance management is operational alerts. Using zALERT, you will want to implement alerts on items such as queue levels, active regions, active terminals, and the number and type of conversational transactions.
With low overhead of processing the transaction and statistics
records, zVPS normally collects and reports data on
a one minute intervals that is aligned
to the minute. During statistics gathering, there is overhead
associated with that inside CICS. Traditionally, this is suspected
to create a performance impact during this very short time frame
of statistics gathering.
If the statistics interval
is 60 seconds, this will impact every 60 seconds, if the interval
is 15 minutes, then this will impact every 900 seconds. One of
the experiments we performed was to show response time second by second.
To run your own benchmark on all CICS in an LPAR, issue the
command
"SMSG ZSERVE SET BENCHMARK sysid jobname"
That will produce one
record every second for 5 minutes showing response time of all
transactions completing in that second. This allows
analysis of the impact of the statistics gathering at the top of the
minute. It also allows quick determination of dyanmic tuning
options or if other workload changes are effective or detrimental
In benchmark mode, zwrite will create a "BENCHMARK FILE" on the ZWRITE 191 disk. The columns are transaction count, Response time, (usrdisp+susptime), usrdispt, susptime, usrcput.
Bench: 17:27:17 VSI1 16 0.008 0.008 0.005 0.003 0.004 Bench: 17:27:18 VSI1 40 0.006 0.006 0.006 0.001 0.005 Bench: 17:27:19 VSI1 87 0.017 0.017 0.006 0.011 0.006 Bench: 17:27:20 VSI1 120 0.036 0.036 0.004 0.032 0.004 Bench: 17:27:21 VSI1 95 0.002 0.002 0.002 0.000 0.002 Bench: 17:27:22 VSI1 87 0.004 0.004 0.003 0.000 0.003 Bench: 17:27:23 VSI1 96 0.004 0.004 0.004 0.001 0.003 Bench: 17:27:24 VSI1 112 0.006 0.006 0.004 0.002 0.004 Bench: 17:27:25 VSI1 64 0.005 0.005 0.004 0.001 0.004
This capability allows immediate analysis of any dynamic tuning performed or to understand impact of other actions.
When there is performance issues, one common question is "what changed". One of the possible changes is transaction loads. If one transaction suddenly ramps up unexpectatdly or in error, this will change performance characteristics. To understand the quantity of transactions by transaction, look at the ZOSCIX3 to see the load by transaction name.
Report: ZOSCIX3 z/OS CICS User Transacti Monitor initialized: 10/20/20 at 17:56:00 on --------------------------------------------- Time/ <--Transaction->SYSID Rate Total Susp Disp APPLID ID Count /Sec Resp Time Time -------- ---- ----- ---- ----- ----- ----- 10/20/20 17:56:00 - 17:57:00 V24A C24ASTND Total 688 11.5 0.016 0.006 0.010 CSAC 55 0.92 0.003 0.001 0.002 STRH 31 0.52 0.059 0.018 0.041 STR1 29 0.48 0.007 0.003 0.004 STR2 28 0.47 0.007 0.000 0.007 STR3 22 0.37 0.013 0.001 0.012 STR4 23 0.38 0.014 0.001 0.014 STR5 21 0.35 0.028 0.005 0.023 STR6 24 0.40 0.021 0.002 0.019 STR7 22 0.37 0.025 0.005 0.020 STR8 25 0.42 0.031 0.007 0.023 STR9 35 0.58 0.047 0.017 0.030 ZIPC 113 1.88 0.006 0.004 0.001 ZIPU 118 1.97 0.004 0.002 0.002 ZPHG 71 1.18 0.014 0.007 0.007 ZPHP 71 1.18 0.022 0.016 0.006
CPU analysis has several different aspects. One can start by understanding the LPAR requirements by looking at the ZOSCPU report. In this case there are two general purpose engines and one zIIP that is not being used.
Report: ZOSCPU Z/OS CPU Report
Monitor initialized: 10/20/20 at 17:56:00 on
--------------------------------------------
TIME/ <--CPU--> Sample <-CPU Utilization>
SYSID ID Type Count Total Wait Parked
------ ---- ---- ----- ----- ----- ------
17:57:00 - 17:58:00
V24A Tot GP 2 22.6 142.2 0
0 GP 1 12.9 68.0 0
1 GP 1 9.7 74.3 0
2 zIIP 1 0.1 100.0 0
After looking at the high level CPU, one can look at the specific CICS region on the ZOSJCPU report.
Report: ZOSJCPU z/OS Job/Step CPU/Resource Report
Monitor initialized: 10/20/20 at 17:56:00 on Z15S serial 0E0F78
------------------------------------------------------------------
SYSID <------JOB----------> <-------CPU Percents---------------->
Name JobID Step Initiat Regn
Nbr Total STD SRB TCB SRB I/O Cntrl USS
---- -------- -------- --- ----- ---- ---- --- --- --- ----- ---
10/20/20
17:56:00 - 17:57:00
V24A
Totals . 19.5 16.0 3.2 0 0 0.3 0 0
CATALOG CATALOG 1 0 0 0 0 0 0 0 0
C24ASTND STC04414 1 13.0 12.4 0.6 0 0 0 0 0
GPMSERVE STC03424 1 0.1 0.1 0 0 0 0 0 0
IXGLOGR IXGLOGR 1 0.0 0 0.0 0 0 0 0 0
IZUSVR1 STC03413 3 0.8 0.8 0.0 0 0 0 0 0
JESXCF JESXCF 1 0.0 0.0 0 0 0 0 0 0
JES2 JES2 1 0.3 0.3 0.0 0 0 0 0 0
JES2MON JES2MON 1 0.3 0.1 0.1 0 0 0 0 0
MQA1CHIN STC03890 1 0.0 0.0 0.0 0 0 0 0 0
MQA1MSTR STC03453 1 0.3 0.1 0.1 0 0 0.0 0 0
MQA2CHIN STC03937 1 0.0 0.0 0.0 0 0 0 0 0
MQA2MSTR STC03456 1 0.0 0.0 0.0 0 0 0 0 0
MSTJCL00 MSTR 1 0.1 0.1 0.0 0 0 0 0 0
OMVS OMVS 1 0.0 0.0 0 0 0 0 0 0
RMF STC03391 1 0.1 0.1 0.0 0 0 0 0 0
SDSF STC03387 1 0.0 0.0 0.0 0 0 0 0 0
SDSFAUX STC03407 1 0.4 0.4 0.1 0 0 0 0 0
SMF SMF 1 0.0 0.0 0 0 0 0 0 0
SMS SMS 1 0.0 0.0 0.0 0 0 0 0 0
TCPIP STC03385 1 0.9 0.2 0.7 0 0 0 0 0
TN3270 STC03421 1 1.4 0.1 1.3 0 0 0 0 0
WLM WLM 1 0.3 0.2 0.0 0 0 0 0 0
XCFAS XCFAS 1 0.1 0.1 0.0 0 0 0 0 0
ZFS STC03381 1 0.2 0.2 0.0 0 0 0 0 0
ZOSMNVM2 STC03419 1 0.3 0.3 0 0 0 0 0 0
ZOSMNVM4 STC03420 1 0.3 0.3 0.0 0 0 0 0 0
And we can see at this point, the CICS region is using 13% of one GP processor.
To take that analsys inside CICS, the totals for all the transactions that do not include CICS overhead shows as 4.9 CPU seconds during the interval, or 8.1% of one GP CPU.
Report: ZOSCIX2 z/OS Region Transaction Analysis Veloc Monitor initialized: 10/20/20 at 17:56:00 on Z15S serial 0E0F78 ------------------------------------------------------------------------ Time/<-Response Time-> <-Total- SYSID/ APPLID Group Count Total Susp Disp CPU DISP ZIP <--CPU-- Time Resp Time Time Time Wait CPU Secs Pct ---- ------- -------- ----- ----- ----- ----- ----- ----- --- ---- --- 10/20/20 17:56:00 - 17:57:00 V24A C24ASTND Totals 688 0.016 0.006 0.010 0.007 0.001 0 4.9 8.1 ------------------------------------------------------------------------ 17:57:00 - 17:58:00 V24A C24ASTND Totals 1192 0.013 0.005 0.008 0.006 0.001 0 6.6 11. InFlight ------------------------------------------------------------------------ 17:58:00 - 17:59:00 V24A C24ASTND Totals 1189 0.013 0.005 0.008 0.006 0.001 0 6.8 11. InFlight 11 119.9 119.7 0.221 0.064 0.024 0 0.7 1.1
CPU by transaction is found on ZOSCIX4, and in this case it is obvious that this workload does not utilize the zIIP processor. The CPU time is per transaction in CPU seconds. In this case the average for ALL the transactions that completed was .007 CPU seconds or 7 milliseconds per transaction.
