CICS excessive response times with MQ input

Raymond Luke · New User Joined: 20 Sep 2014 Posts: 2 Location: USA

We are executing CICS TS 4.2 with transaction rate of 4 to 5 million a day.
We usually get sub-second response time.
There are about 4,000 MQ transactions each day in the mix with sub-second response time
We are about to implement a project with many more MQ transactions.
We currently execute about 700 of one of the new transactions in production each day QIN2.
While we execute up to 150 transactions per second, up to 16 of the QIN2 are completed in the 150.
In production we are using 1 input queue which initiates 1 MQ task MQIP, to retrieve the data from the queue followed by the application QIN2

We are testing an environment where we are using 4 queues which will initiate the MQIP task for each queue followed by the QIN2.
The 4 queues were instituted to balance the the number of calls to the system.
We stress test the calls in the test system with all 4 queues and got sub-second response time.

We stress test the calls in the production environment using the 4 queues while executing 150 normal transactions per second.
we entered 850 MQ calls to the system at the rate of 4 calls per second.
About 10% of the QIN2 transactions experience excessive response times,from 1 second to 10 seconds.

After the test was completed we began experiencing slow response times for our normal transactions up to 30 minutes after the test.

We have 2 problems.
What is causing the slow response times for 10% of the QIN2 transaction
What is the cause of the residual effect on the system where normal transactions are executing at 1 through 10 second response times.

Did anyone experience such anomaly before or have any ideas what we can try?

The transaction and program are defined below.

TRANSACTION(QIN2) GROUP(PCTIVR)
PROGRAM(CMQ96202) TWASIZE(1200) PROFILE(XXXXC481)
STATUS(ENABLED) TASKDATALOC(ANY) TASKDATAKEY(USER)
STORAGECLEAR(NO) RUNAWAY(SYSTEM) SHUTDOWN(DISABLED) ISOLATE(YES)
DYNAMIC(NO) ROUTABLE(NO) PRIORITY(100) TRANCLASS(DFHTCL00)
DTIMOUT(NO) RESTART(NO) SPURGE(NO) TPURGE(NO) DUMP(YES)
TRACE(YES) CONFDATA(NO) OTSTIMEOUT(NO) ACTION(BACKOUT) WAIT(YES)
WAITTIME(0,0,0) RESSEC(NO) CMDSEC(NO)

Program(CMQ96202)
Length(0000026576)
Language(Cobol)
Progtype(Program)
Status( Enabled )
Sharestatus( Private )
Copystatus( Notrequired )
Cedfstatus( Cedf )
Dynamstatus(Notdynamic)
Dataloc(Below)
Execkey(Uexeckey)
Executionset( Fullapi )
Concurrency(Quasirent)
Apist(Cicsapi)
Remotesystem()
Runtime( Lenv )
Installagent(Autoinstall)
Definesource(DFHPGADX)

Rohit Umarjikar · Posted: Wed Sep 24, 2014 6:30 am

What was the findings for those 10 % of records? Did you take any one request and backtracked to why and which source caused this or did something on hold which caused more I/O waiting?

Bill O'Boyle · Posted: Wed Sep 24, 2014 7:40 pm

Is there actual VSAM I-O being performed (mostly PUTS)? How about DB2 and/or IMS PUT's?

In Production, are your transid's competing with higher priority transid's?

Ask your CICS Sysprog if your transid's are defined to a specific TRANCLASS, reducing the number of active transid's which can execute concurrently.

Are you using STROBE (or a facsimile) to measure transaction-time?

You can get some idea of the bottleneck with a TRACE and review the API's and times.

Sometimes the difference between TEST and PROD can be quite different.

Welcome to the forum....

Raymond Luke · New User Joined: 20 Sep 2014 Posts: 2 Location: USA

To answer your questoin Rohit I printed the detail of TMON stats for a QIN2 run in production.
There were 700 entered executed in sub second response time.

And the QIN2s that were run in the sress test where we had problems.
The detail showed high I/O waits which we cannot explain

====================================================================================

This QIN2 transaction ran while we were were processing 140 trans per sec using the 1 queue
which is run every day with mix of normal transactions.
The response time is .0386 sec and similar for the 700 QIN2s executed at that time
This is a TMON detail stat of a QIN2 at that time.

TRANID: QIN2 TERMID: SYSID: RPRB START DATE: 09/24/14
ORIG TRN: QIN2 LUNAME: SMFSID: DD68 TIME: 9:30:04.1878
BASE PGM: CMQ96202 REMOTE: IMAGE: DSYS STOP DATE: 09/24/14
CTASK#: 31999 USERID: CISPRBB ASID: 0096 TIME: 9:30:04.2264
MTASK#: 731249 OPERID: GROUP: CICSPROD JOBNAME: PCISLDS1

ELAP: 0.0386 RESPONSE: 0.0386 WORKLOAD: TRANCLASS:
DISP: 0.0162 WT1STDSP: 0.0001 SRVCLASS: PRIORITY: 100
WAIT: 0.0224 CPU TIME: 0.0129 RPTCLASS: MQQUE MGR:
STD CP: 0.0000 ELIGIBLE: 0.0000
USER24HWM: 6,912 USER31HWM: 722,864 USER64HWM: 0 TOT GETMAINS: 13
CICS24HWM: 0 CICS31HWM: 18,976 CICS64HWM: 0 TIOA STG HWM: 0

TERMTYPE: 00 INPUT CNT: 0 INPUT SIZE: 0 ABEND CODE:
3270 AID: 00 OUTPUT CNT: 0 OUTPUT SIZE: 0 ABEND PGM:

FLAGS: ATI PGMF EIP ICP FCP TSP JCP EXHT BKG C670 TM34 T01
USERFLD:
UOW: CONED.CISPRB : CDFF73B0DC62 : 0001 LOC UOW: CDCDFF73B0DC6283

JOBNAME: PCISLDS1 TRANSACTION: QIN2 #31999
TIMING TYPE COUNT TOT TIME AVG TIME % OF RESPONSE
------------------
* TIMING OVERVIEW
------------------
+ RESPONSE TIME 1 0.0386 0.0386 100.00
+ OPERATOR WAIT 0 0.0000 0.0000 0.00
------------------
= TOTAL TX TIME = 1 0.0386 0.0386 100.00
------------------
+ TASK DISP TIME 13 0.0162 0.0013 42.04
+ TASK WAIT TIME 14 0.0224 0.0016 57.95
...INIT WAIT 2 0.0001 0.0001 0.26
...WAIT MVS 6 0.0180 0.0030 46.68
...WAIT OLDC 0 0.0000 0.0000 0.00
...WAIT OLDW 0 0.0000 0.0000 0.00
...SUSP TIME 0 0.0000 0.0000 0.00
...TCB SWITCH 6 0.0043 0.0007 10.99
WAIT ON REDISPATCH 0 0.0000 0.0000 0.00
------------------
* REQUEST SUMMARY
------------------
TOTAL I/O REQUESTS 39 0.0198 0.0005 51.33
MRO/ISC REQUESTS 0 0.0000 0.0000 0.00
EXCEPTION WAIT 0 0.0000 0.0000 0.00
TERMINAL WAIT 0 0.0000 0.0000 0.00
STORAGE WAIT 0 0.0000 0.0000 0.00
ALL EIP REQUESTS 537 0.0222 0.0000 57.59
ALL EIP REQ WAIT 0 0.0000 0.0000 0.00
FCP REQUESTS 39 0.0198 0.0005 51.33
FCP REQ WAIT 6 0.0180 0.0030 46.68
DLI REQUESTS 0 0.0000 0.0000 0.00
DLI REQ WAIT 0 0.0000 0.0000 0.00
DB2 REQUESTS 0 0.0000 0.0000 0.00

FILE/DB TYPE VOLSER EC BRW GET UPD ADD DEL COUNT TOT TIME AVG TIME
* * * * * * * * * * * *
ACCTIDX0 VSAM CIXQ91 00 0 1 0 0 0 1 0.0007 0.0007
ACTPRIM0 VSAM CIXQ91 00 36 0 0 0 0 36 0.0100 0.0003
AVAYALOG VSAM CIXLB2 00 0 0 0 1 0 1 0.0016 0.0016
MASTERS0 VSAM CIXMSA 00 0 1 0 0 0 1 0.0076 0.0076

ID CPU TCB SWCT TCB SWTM WRD CNT WRD TIME TOT CNT TOT TIME
* * * * * * * *
L8 0.0019 3 0.0003 0 0.0000 3 0.0039
QR 0.0110 3 0.0040 0 0.0000 10 0.0123

================================================================================
This is one of the QIN2 that was part of the 10% with response time over 1.0 seconds.
Response time was 10.7393 seconds. There were 850 QIN2 transactions entered at 2 per sec
and the response time began increasing over 1.0 second after approximately 500 transactions.
The system was executing over 110 transactions per sec at that time.
The wait times were attributed to File I/O but there is no reason for it.

APPLID : TMNDCICS TIME: 19:47:59
COMMAND: CYCLE: MMSS
_NEXT? _GNXT? _MENU?
TRANID: QIN2 TERMID: SYSID: RPRB START DATE: 09/19/14
ORIG TRN: QIN2 LUNAME: SMFSID: DD68 TIME: 12:11:36.0281
BASE PGM: CMQ96202 REMOTE: IMAGE: DSYS STOP DATE: 09/19/14
CTASK#: 13044 USERID: CISPRBB ASID: 014A TIME: 12:11:46.7674
MTASK#: 1811125 OPERID: GROUP: CICSPROD JOBNAME: PCISLDS1

ELAP: 10.7393 RESPONSE: 10.7393 WORKLOAD: TRANCLASS:
DISP: 0.0214 WT1STDSP: 0.1243 SRVCLASS: PRIORITY: 100
WAIT: 10.7179 CPU TIME: 0.0144 RPTCLASS: MQQUE MGR:
STD CP: 0.0000 ELIGIBLE: 0.0000
USER24HWM: 36,224 USER31HWM: 722,784 USER64HWM: 0 TOT GETMAINS: 14
CICS24HWM: 0 CICS31HWM: 18,976 CICS64HWM: 0 TIOA STG HWM: 0

TERMTYPE: 00 INPUT CNT: 0 INPUT SIZE: 0 ABEND CODE:
3270 AID: 00 OUTPUT CNT: 0 OUTPUT SIZE: 0 ABEND PGM:

FLAGS: ATI PGMF EIP ICP FCP TSP JCP EXHT BKG C670 TM34 T01
USERFLD:
UOW: CONED.CISPRB : C7DA3B5D38F7 : 0001 LOC UOW: CDC7DA3B5D38F783

JOBNAME: PCISLDS1 TRANSACTION: QIN2 #13044
TIMING TYPE COUNT TOT TIME AVG TIME % OF RESPONSE
------------------
* TIMING OVERVIEW
------------------
+ RESPONSE TIME 1 10.7393 10.7393 100.00
+ OPERATOR WAIT 0 0.0000 0.0000 0.00
------------------
= TOTAL TX TIME = 1 10.7393 10.7393 100.00
------------------
+ TASK DISP TIME 13 0.0214 0.0017 0.19
+ TASK WAIT TIME 14 10.7179 0.7656 99.80
...INIT WAIT 2 0.1243 0.0622 1.15
...WAIT MVS 5 5.9073 1.1815 55.00
...WAIT OLDC 0 0.0000 0.0000 0.00
...WAIT OLDW 0 0.0000 0.0000 0.00
...SUSP TIME 1 3.2463 3.2463 30.22
...TCB SWITCH 6 1.4400 0.2400 13.40
WAIT ON REDISPATCH 0 0.0000 0.0000 0.00
------------------
* REQUEST SUMMARY
------------------
TOTAL I/O REQUESTS 37 9.1559 0.2475 85.25
MRO/ISC REQUESTS 0 0.0000 0.0000 0.00
EXCEPTION WAIT 0 0.0000 0.0000 0.00
TERMINAL WAIT 0 0.0000 0.0000 0.00
STORAGE WAIT 0 0.0000 0.0000 0.00
ALL EIP REQUESTS 492 9.1585 0.0186 85.27
ALL EIP REQ WAIT 0 0.0000 0.0000 0.00
FCP REQUESTS 37 9.1559 0.2475 85.25
FCP REQ WAIT 6 9.1536 1.5256 85.23
DLI REQUESTS 0 0.0000 0.0000 0.00
DLI REQ WAIT 0 0.0000 0.0000 0.00
DB2 REQUESTS 0 0.0000 0.0000 0.00
------------------
DB2 REQ WAIT 0 0.0000 0.0000 0.00
UDB REQUESTS 0 0.0000 0.0000 0.00
TEMP STG REQUESTS 35 0.0005 0.0000 0.00
TEMP STG REQ WAIT 0 0.0000 0.0000 0.00
TRANSDATA REQUESTS 0 0.0000 0.0000 0.00
TRANSDATA REQ WAIT 0 0.0000 0.0000 0.00
JCP REQUESTS 1 0.0001 0.0001 0.00
JCP REQ WAIT 0 0.0000 0.0000 0.00
PGM FETCH REQUESTS 3 0.0000 0.0000 0.00
PGM FETCH REQ WAIT 0 0.0000 0.0000 0.00
SPOOL REQUESTS 0 0.0000 0.0000 0.00
SPOOL REQ WAIT 0 0.0000 0.0000 0.00
FEPI REQUESTS 0 0.0000 0.0000 0.00
FEPI REQ WAIT 0 0.0000 0.0000 0.00
GDS REQUESTS 0 0.0000 0.0000 0.00
------------------
GDS REQ WAIT 0 0.0000 0.0000 0.00
RDO REQUESTS 0 0.0000 0.0000 0.00
RDO REQ WAIT 0 0.0000 0.0000 0.00
MQS REQUESTS 0 0.0000 0.0000 0.00
MQS REQ WAIT 0 0.0000 0.0000 0.00
MQOPEN CALLS 0 0.0000 0.0000 0.00
MQCLOSE CALLS 0 0.0000 0.0000 0.00
MQGET CALLS 0 0.0000 0.0000 0.00
MQPUT CALLS 0 0.0000 0.0000 0.00
MQPUT1 CALLS 0 0.0000 0.0000 0.00
MQINQ CALLS 0 0.0000 0.0000 0.00
MQSET CALLS 0 0.0000 0.0000 0.00
USERWAIT 0 0.0000 0.0000 0.00
------------------

JOBNAME: PCISLDS1 TRANSACTION: QIN2 #13044
DB2 SUBSYS: DBCTL REGION: THREAD CPU: 0.0000
FILE/DB TYPE VOLSER EC BRW GET UPD ADD DEL COUNT TOT TIME AVG TIME
* * * * * * * * * * * *
ACCTIDX3 VSAM CIXW91 00 0 1 0 0 0 1 0.0012 0.0012
ACTPRIM3 VSAM CIXW92 00 30 0 0 0 0 30 2.0885 0.0696
AVAYALOG VSAM CIXLB2 00 0 0 0 1 0 1 0.0039 0.0039
MASTERS3 VSAM CIXMS9 00 0 1 0 0 0 1 5.4093 5.4093
TELEIDX VSAM CIXLB1 00 4 0 0 0 0 4 1.6530 0.4132

============================================================================

The other questions raised.
Is there actual VSAM I-O being performed (mostly PUTS)? How about DB2 and/or IMS PUT's?
There is no DB2 and no IMS
There is 1 VSAM put on an ESDS file for logging

In Production, are your transid's competing with higher priority transid's?
You are correct about the priority. It was left unnoticed.
QIN2 is running at 100 whereas all other transactions are at 228. We will change it to 228
The MQIP which reads the queue is set at 250.
The priority does not affect the QIN2s that run every day in production.

Ask your CICS Sysprog if your transid's are defined to a specific TRANCLASS, reducing the number of active transid's which can execute concurrently.
All the Transactions run in the same class. there is no limit.

You can get some idea of the bottleneck with a TRACE and review the API's and times.
We will be running some traces the next few days when there is a window to do the stress test again.

Rohit Umarjikar · Posted: Sat Sep 27, 2014 3:13 am

Please refer to this ppt which describes these parameters in detail and if you know them all then just ignore this And meanwhile, I would also try to see if I get something more.

www-01.ibm.com/support/docview.wss?uid=swg27015047&aid=1

Joao Lima · New User Joined: 27 Nov 2014 Posts: 1 Location: BRAZIL

I have a similar problem...

Raymond, you solved the problem of excessive response time with MQ?