Monitoring application program elapsed time
The IMS Monitor can record measurements of elapsed times for each transaction and scheduling of an application program. It does this during the monitored interval while other programs are executing concurrently.
Elapsed times are calculated from the start of the first DL/I (or other) call to the end of that program. You can distinguish between time spent in application code and in DL/I processing. The following figure illustrates the event intervals.
Within the elapsed time for a DL/I call, the wait time to obtain segment data is recorded separately. Similarly, within the elapsed time for an external subsystem call, the processing time in the external subsystem is recorded separately as the wait time. For regions designated as wait-for-input, the time spent waiting for input messages is excluded from values shown in the reports. The application processing (A/P) time includes many kinds of subsidiary service beyond the machine cycles expended by the program object code—such as subroutine loading, I/O to z/OS® data sets, and any overlay processing. If the program is waiting to be dispatched or requires paging before it can use real storage, these delays are also accounted for in application program processing time. Because a program can execute many transactions for each schedule, the elapsed time from schedule to first call is recorded separately. This time covers the initialization performed by the application program and includes the time for loading the program.
The elapsed times are given in the Program Summary report. The following example is a sample of the report. Programs are identified by their PSB name on individual lines in the report. Each line gives a summary of the activity for that PSB during the measured interval. The total number of schedules, DL/I calls, transactions completed (dequeued), and waits for DL/I call I/O and external subsystem processing are given. The report line gives calculated average times for:
- Elapsed time per schedule
- Processor time per schedule
- Schedule to first DL/I call per schedule
- Elapsed time per transaction
The report also includes:
- Frequencies for calls per transaction
- I/O waits per DL/I call
- Waits per external subsystem call
- Transactions dequeued per schedule
A TOTALS line summarizes all activity for the PSBs active during the monitored interval. (The PSB DUMMY line reconciles any incomplete scheduling caused by a region stopping during scheduling or for a program that experiences a pseudo abend.)
IMS MONITOR ****PROGRAM SUMMARY**** TRACE START 1993 130 5:55:15 TRACE STOP 1993 130 5:59:49 PAGE 0075
(A)........(B)........ (A)........(B)........
I/O TRAN. CPU . ELAPSED SCHED.TO . ELAPSED
NO. TRANS. CALLS I/O IWAITS DEQD. TIME DISTR. TIME 1ST CALL DISTR. TIME
PSBNAME SCHEDS. DEQ. CALLS /TRAN IWAITS /CALL /SCH. /SCHED. NO. /SCHED. /SCHED. NO. /TRANS.
_______ _______ ____ _____ _____ ______ _____ _____ _______ ___ _______ _______ ___ _______
PROGSC6D 1 13 60 4.6 46 0.7 13.0 10010 884A,B 290146255 15479797 886A,B 22318942
PROGIT8C 3 17 225 13.2 166 0.7 5.6 90592 888A,B 256617508 73283259 890A,B 45285442
PROGTS1C 2 25 47 1.8 0 0.0 12.5 10010 892A,B 239190808 7586234 894A,B 19135264
PROGPS3D 1 23 792 34.4 182 0.2 23.0 10010 896A,B 322812716 48146258 898A,B 14035335
PROGPS3A 13 36 1246 34.6 267 0.2 2.7 49782 900A,B 32801812 2228611 902A,B 11845098
PROGIT1B 11 21 99 4.7 0 0.0 1.9 6341 904A,B 23212388 2036217 906A,B 12158870
PROGSC2B 7 155 3068 19.7 1845 0.6 22.1 346112 908A,B 93655514 789390 910A,B 4229603
PROGIT8A 12 28 434 15.5 293 0.6 2.3 34350 912A,B 30196795 1745815 914A,B 12941483
PROGPS2C 1 10 179 17.9 205 1.1 10.0 10010 916A,B 221024429 53642029 918A,B 22102442
PROGTS1B 8 20 54 2.7 0 0.0 2.5 5447 920A,B 39943245 2895 922A,B 15977298
PROGPS3C 1 14 468 33.4 117 0.2 14.0 10010 924A,B 310644485 35978027 926A,B 22188891
PROGIT1C 1 9 32 3.5 0 0.0 9.0 10010 930A,B 304892631 30226173 932A,B 33876959
PROGSC2C 1 9 160 17.7 101 0.6 9.0 10010 934A,B 296909110 22242652 936A,B 32989901
PROGIT2B 8 21 393 18.7 63 0.1 2.6 21703 938A,B 35126671 1798496 940A,B 13381589
PROGIT2C 6 17 211 12.4 39 0.1 2.8 13312 942A,B 288883508 50698467 944A,B 101958885
PROGTS1D 2 26 50 1.9 0 0.0 13.0 10010 950A,B 284944505 10613350 952A,B 21918808
PROGPS3B 8 22 770 35.0 169 0.2 2.7 35737 954A,B 38016279 2149158 956A,B 13824101
PROGIT1A 11 24 106 4.4 0 0.0 2.1 7925 958A,B 30883486 1935855 960A,B 14154931
PROGSC4A 9 163 1775 10.8 5101 2.8 18.1 235921 963A,B 62172947 3011199 965A,B 3432862
PROGSC6C 1 10 44 4.4 38 0.8 10.0 10010 967A,B 228098334 46568124 969A,B 22809833
PROGPS2B 11 28 557 19.8 604 1.0 2.5 35069 971A,B 33309266 1181831 973A,B 13085783
PROGIT8D 1 12 175 14.5 133 0.7 12.0 10010 975A,B 253392289 21274169 977A,B 21116024
PROGSC4C 1 10 98 9.8 349 3.5 10.0 10010 979A,B 248736332 25930126 981A,B 24873633
PROGSC6A 7 157 789 5.0 457 0.5 22.4 11703 983A,B 73936039 115979 985A,B 3296511
PROGIT2A 7 22 430 19.5 71 0.1 3.1 28529 987A,B 37905001 2982 989A,B 12060682
PROGSC2D 1 15 280 18.6 180 0.6 15.0 10010 991A,B 316194222 41527764 993A,B 21079614
PROGPS2A 6 25 490 19.6 548 1.1 4.1 43177 995A,B 58277945 2467506 997A,B 13986707
PROGSC2A 5 121 2363 19.5 1420 0.6 24.2 276187 1001A,B 88906184 6022954 1003A,B 3673809
PROGIT2D 1 20 361 18.0 62 0.1 20.0 10010 1005A,B 386092737 111426279 1007A,B 19304636
PROGSC4B 10 131 1421 10.8 4115 2.8 13.1 617016 1011A,B 53826667 2632409 1013A,B 4108905
PROGSC4D 1 19 197 10.3 668 3.3 19.0 10010 1020A,B 227999124 46667334 1022A,B 11999953
PROGPS2D 1 13 240 18.4 291 1.2 13.0 10010 1025A,B 327602445 52935987 1027A,B 25200188
PROGSC6B 5 140 694 4.9 395 0.5 28.0 16884 1032A,B 78994223 3290769 1034A,B 2821222
PROGIT1D 1 10 36 3.6 0 0.0 10.0 10010 1041A,B 290379922 15713464 1043A,B 29037992
PROGIT8B 8 17 288 16.9 190 0.6 2.1 33436 1259A,B 35223857 2902 1261A,B 16575932
**TOTALS 173 1403 18632 13.2 18115 0.9 8.1 90328 82303700 2972755 10148638You can use the Call-Summary report to examine the detail of the call processing for each program. The report is itemized by type of call and summarized for the monitor interval. An extract from the multipage output is given in the following example. The calls using an I/O PCB are given first and sub-totaled. Then, the total calls of each type, against each database PCB and each external subsystem, are listed. The PSB TOTAL line marks the end of data for each program.
IMS MONITOR ****CALL SUMMARY**** TRACE START 1993 130 5:55:15 TRACE STOP 1993 130 5:59:49 PAGE 0186
(C) (A) (B)
CALL LEV STAT IWAITS/ ..ELAPSED TIME... .NOT IWAIT TIME.. DISTRIB.
PSB NAME PCB NAME FUNC NO.SEGMENT CODE CALLS IWAITS CALL MEAN MAXIMUM MEAN MAXIMUM NUMBER
___ ____ ___ ____ ____ __________ ____ _____ ______ ____ ____ _______ ____ _______ ______
PROGSC6B I/O PCB ISRT ( ) 138 0 0.00 372 1240 372 1240 598A,B,C
GU ( ) 134 133 0.99 2600917 20974615 2587532 20962866 602A,B,C
(GU) ( ) 3 0 0.00 15 16 15 16 716A,B,C
ASRT ( ) 3 0 0.00 330 333 330 333 869A,B,C
GU ( ) QC 2 1 0.50 17639806 21219588 17634776 21209529 870A,B,C
I/O PCB SUBTOTAL
___ ___ ________ 280 134 0.47 1370910 1364469
INVENTRB DLET (03)IN060SUP 138 0 0.00 813 1289 813 1289 599A,B,C
GNP (03)IN060SUP 138 7 0.05 2112 112589 1047 112589 600A,B,C
GU (01)IN010PAR 138 254 1.84 29511 75356 1195 19229 601A,B,C
DL/I PCB SUBTOTAL
____ ___ ________ 414 261 0.63 10812 1018
PSB TOTAL
___ _____ 694 395 0.56 559555 551114
PROGSC2A I/O PCB ISRT ( ) 118 0 0.00 381 1496 381 1496 603A,B,C
GU ( ) 114 284 2.49 3304809 21784513 3164423 21664181 632A,B,C
(GU) ( ) 2 0 0.00 17 18 17 18 781A,B,C
ASRT ( ) 3 0 0.00 367 444 367 444 871A,B,C
GU ( ) QC 2 5 2.50 19931897 20045206 19799530 19925277 872A,B,C
I/O PCB SUBTOTAL
___ ___ ________ 239 289 1.20 1743339 1675270
LOGVENDA REPL (03)IN040SLQ 118 0 0.00 268 804 268 804 604A,B,C
GNP (03)IN040SLQ 118 5 0.04 899 16995 218 305 605A,B,C
REPL (02)VN030PAR 826 0 0.00 805 1578 805 1578 606A,B,C
GNP (02)VN030PAR 826 873 1.05 19321 94521 456 1363 607A,B,C
REPL (01)VN020REO 118 58 0.49 8879 48076 832 1682 623A,B,C
GU (01)VN020REO 118 195 1.65 31688 360775 1300 1746 625A,B,C
DL/I PCB SUBTOTAL
____ ___ ________ 2124 1131 0.53 10145 636
PSB TOTAL
___ _____ 2363 1420 0.60 185445 170013
PROGSC2D I/O PCB ISRT ( ) 14 0 0.00 377 621 377 621 608A,B,C
GU ( ) 14 36 2.57 22360408 52048566 22221852 51901313 634A,B,C
I/O PCB SUBTOTAL
___ ___ ________ 28 36 1.28 11180393 11111115
LOGVENDD REPL (03)IN040SLQ 14 0 0.00 263 328 263 328 609A,B,C
GNP (03)IN040SLQ 14 1 0.07 1407 16889 223 307 610A,B,C
REPL (02)VN030PAR 98 0 0.00 820 1015 820 1015 611A,B,C
APOL1 I/O PCB ASRT (..)........ 3
(GU) (..)........ 3
INQY (..)........ 2
I/O PCB SUBTOTAL
___ ___ ________ 8
OTMDEST1 ICAL (..)........ .. 4
DL/I PCB SUBTOTAL
____ ___ ________ 4
PSB TOTAL
___ _____ 12