Examining scheduling activity

Using the data extracted by the Log Transaction Analysis utility you can examine the effect of your scheduling algorithm.

Each occurrence of a transaction primarily indicates:

Message priority and message class
Time in input queue
Time to process
Time in output queue
Total time-in-system (measured between completion of message queue input to retrieval for output)

You can look at the processing type 'S' entries to see the send and receive times. You can sort the detail report lines by transaction code and look at any critical transactions requiring rapid response time. Refer to the following example for details on each table line item.

12.50.11 JOB00386  $HASP373 DFSILTA4 STARTED - INIT 4    - CLASS K - SYS STL1
12.50.12 JOB00386  SMF000I  DFSILTA4    ILTA        DFSILTA0    0000
12.50.12 JOB00386  $HASP395 DFSILTA4 ENDED
------ JES2 JOB STATISTICS ------
  05 JUN 2007 JOB EXECUTION DATE
           30 CARDS READ
          143 SYSOUT PRINT RECORDS
            0 SYSOUT PUNCH RECORDS
           10 SYSOUT SPOOL KBYTES
         0.01 MINUTES EXECUTION TIME
        1 //DFSILTA4 JOB 'TERRY',CLASS=K,MSGCLASS=A,MSGLEVEL=(1,1),               JOB00386
          // REGION=0M,TIME=1440,
          // USER=USRID01,PASSWORD=
          /*ROUTE PRINT THISCPU/IMSTST45
        2 //JOBLIB   DD DSN=IMSTESTL.TNUC0,DISP=SHR
        3 //         DD DSN=IMSBLD.I10RTS17.CRESLIB,DISP=SHR
        4 //ILTA     EXEC PGM=DFSILTA0
        5 //HEADING  DD SYSOUT=A
        6 //PRINTER  DD SYSOUT=A
        7 //SYSUDUMP DD SYSOUT=A
        8 //REPORT   DD DUMMY
        9 //TITLE    DD *
          //*
          //* LOG INPUT FOLLOWS...
          //*
       10 //LOGIN0A  DD DSN=IMSTESTL.SLDSP.IMSA.TYTY,DISP=SHR,
          //         UNIT=SYSDA,VOL=SER=DSHR03
       11 //LOGIN01  DD DSN=IMSTESTL.SLDSP.IMS1.TYTY,DISP=SHR,
          //         UNIT=SYSDA,VOL=SER=DSHR03
       12 //LOGIN02  DD DSN=IMSTESTL.SLDSP.IMS2.TYTY,DISP=SHR,
          //         UNIT=SYSDA,VOL=SER=DSHR03
       13 //LOGIN03  DD DSN=IMSTESTL.SLDSP.IMS3.TYTY,DISP=SHR,
          //         UNIT=SYSDA,VOL=SER=DSHR03
ICH70001I USRID01  LAST ACCESS AT 12:50:09 ON TUESDAY, JUNE 5, 2007
IEF236I ALLOC. FOR DFSILTA4 ILTA
IEF237I 04A1 ALLOCATED TO JOBLIB
IEF237I 04B4 ALLOCATED TO
IEF237I JES2 ALLOCATED TO HEADING
IEF237I JES2 ALLOCATED TO PRINTER
IEF237I JES2 ALLOCATED TO SYSUDUMP
IEF237I DMY  ALLOCATED TO REPORT
IEF237I JES2 ALLOCATED TO TITLE
IEF237I 04A9 ALLOCATED TO LOGIN0A
IEF237I 04A9 ALLOCATED TO LOGIN01
IEF237I 04A9 ALLOCATED TO LOGIN02
IEF237I 04A9 ALLOCATED TO LOGIN03
IEF237I 04A9 ALLOCATED TO LOGIN04
IEF237I 04A9 ALLOCATED TO LOGIN05
IEF237I 04A9 ALLOCATED TO LOGIN036
IEF142I DFSILTA4 ILTA - STEP WAS EXECUTED - COND CODE 0000
IEF285I   USRID01.DFSILTA4.JOB00386.D0000102.?         SYSOUT
IEF285I   USRID01.DFSILTA4.JOB00386.D0000103.?         SYSOUT
IEF285I   USRID01.DFSILTA4.JOB00386.D0000104.?         SYSOUT
IEF285I   USRID01.DFSILTA4.JOB00386.D0000101.?         SYSIN
IEF285I   IMSTESTL.SLDSP.IMSA.TYTY                     KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP.IMS1.TYTY                     KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP.IMS2.TYTY                     KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP.IMS3.TYTY                     KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP2.IMS1.TYTY                    KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP2.IMS2.TYTY                    KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF285I   IMSTESTL.SLDSP2.IMS3.TYTY                    KEPT
IEF285I   VOL SER NOS= DSHR03.
IEF373I STEP/ILTA    /START 2007156.1250
IEF374I STEP/ILTA    /STOP  2007156.1250 CPU    0MIN 00.02SEC SRB    0MIN 00.01SEC VIRT    16K SYS   296K EXT     808K SYS   11924K
IEF285I   IMSTESTL.TNUC0                               KEPT
IEF285I   VOL SER NOS= USER01.
IEF285I   IMSBLD.I10RTS17.CRESLIB                      KEPT
IEF285I   VOL SER NOS= MVSS16.
IEF375I  JOB/DFSILTA4/START 2007156.1250
IEF376I  JOB/DFSILTA4/STOP  2007156.1250 CPU    0MIN 00.02SEC SRB    0MIN 00.01SEC
 SPECIFIED START TIME IS 16:53:47.3
 TO END OF FILE PROCESSED 9 TRANSACTIONS THIS RUN
 REPORT CONTAINS 14 COMPLETE RECORD SETS
 IMS LOG DATA FOR IMS3 STARTS AT TIME = 12:47:41.8, DATE = 2007.156
     JOB      STEP    DR     CLASSES
     NAME     NAME    ID ***************
   MPP1     MPP        1   1   2   3   4
   MPP2     MPP        1   1   2   3   4
   MPP3     MPP        1   1   2   3   4
 IMS LOG DATA FOR IMS2 STARTS AT TIME = 12:46:39.5, DATE = 2007.156
 IMS LOG DATA FOR IMS1 STARTS AT TIME = 12:34:26.8, DATE = 2007.156
 IMS LOG DATA FOR IMSA STARTS AT TIME = 12:36:56.8, DATE = 2007.156
 SEQ    TRANS  P   C  ***IN***   ***OUT**  P   PGM     DR SMB*ENQ  MSG*SCHD CNT*ENQ  MSG*END  CNT*GU  SYS IN Q   PROC   OUT Q  TOTAL
 NBR    CODE   R   L  LTERM      LTERM     T   NAME    ID HHMMSST  HHMMSST  HHMMSST  HHMMSST  HHMMSST  ID SSSST  SSSST  SSSST  SSSST
------------------------------------------------------------------------------------------------------------------------------------
00001  CHKPT   0001************************               1234270  1234270  1234270  1234270  1234270 1
00002  CHKPT   0001************************               1236569  1236569  1236569  1236569  1236569 A
00003  CHKPT   0001************************               1239165  1239165  1239165  1239165  1239165 2
00004  CHKPT   0001************************               1240111  1240111  1240111  1240111  1240111 3
00005                 CTRLA02    CTRLA02   M                                1241134           1241135 2 2                   1
00006                 CTRL       CTRL      M                                1241260           1241263 3 3                   2
00007                 CTRLA02    CTRLA02   M                                1241398           1241401 2 2                   2
00008                 CTRL       CTRL      M                                1241523           1241526 3 3                   2
00009                 CTRL       CTRL      M                                1242176           1242179 3 3                   3
00010                 CTRL       CTRL      M                                1242240           1242244 3 3                   3
00011 TRAN21V0 1   1  L62MVS1    L62MVS1   S PGM2V0     1 1242411  1242411  1242413  1242413  1242414 131     0      2      1      3
00012 SMQR21C0 1   1  L62MVS1    L62MVS1   S PGM2C0     1 1242419  1242419  1242421  1242421  1242424 131     0      1      3      5
00013                 CTRLA01    CTRLA01   M                                1242582           1242585 1 1                   2
00014                 CTRLA01    CTRLA01   M                                1243136           1243138 1 1                   1
00015 SMQR21C0 1   1  L62MVS1    L62MVS1   S PGM2C0     1 1243147  1243147  1243149  1243149  1243150 131     0      1      1      3
00016 SMQR21C0 1   1  L62MVS1              T PGM2C0     1 1243279  1243279           1243281          13      0      1             2
00017                 CTRL       CTRL      M                                1243450           1243453 3 3                   2
00018 CONV21V0 1   1  L62MVS1              D CPGM2V0    1 1243498  1243499           1243506          13      0      7             8
00019 CONV21V0 1   1  L62MVS1    L62MVS1   C CPGM2V0    1 1243545  1243545  1243546  1243546  1243546 133     0      0      0 ******
00020 CONV21V0 1   1  L62MVS1    L62MVS1   C CPGM2V0    1 1243577  1243577  1243577  1243577  1243577 133     0      0      0 ******
00021 CONV21V0 1   1  L62MVS1    L62MVS1   C CPGM2V0    1 1244049  1244049  1244049  1244049  1244049 133     0      0      0 ******
00022 CONV21V0 1   1  L62MVS1    L62MVS1   C CPGM2V0    1 1244080  1244080  1244081  1244081  1244081 133     0      0      0 ******
00026  CHKPT   0002************************               1248342  1248342  1248342  1248342  1248342 A
00027  CHKPT   0002************************               1249068  1249068  1249068  1249068  1249068 1
00028  CHKPT   0002************************               1249365  1249365  1249365  1249365  1249365 2
00029  CHKPT   0002************************               1250062  1250062  1250062  1250062  1250062 3

Table 1. Log Analysis report line format
Identification	Starting position	Length	Note
Sequence Number	1	5	1
Transaction Code	7	8
Priority of Transaction (PR)	16	1
Class of Transaction (CL)	18	3
Input LTERM name	22	8
Output LTERM name	33	8
Processing Type (PT)	44	1	2
Program Name	46	8
Dependent Region ID	55	3
Time of SMB Enqueue (Transaction received)	59	7	3
Time of Message Schedule or GU	68	7	3
Time of CNT Enqueue (Message put on output queue)	77	7	3
Time of Program End or Next Message GU	86	7	3
Time of CNT `GU` (Output message starts to terminal)	95	7	3
System IDs (from LOGINxxx DD statement)	103	3
Time in Input Queue	106	6	4, 5
Time Processing	113	6	5, 6
Time in Output Queue	120	6	5, 7
Total Time	127	6	5, 8

Key to the table:

Starting position 1 is a carriage control character which alters the starting positions of the fields when producing a report on disk.
Processing types:

A

Abended transaction

C

Conversational Send/Receive Processing

D

Transmit Only Conversational Processing

F

/FORMAT entered (Transaction Code Field has MODNAME)

M

Message Switch

O

Region Occupancy (A region is occupied by a program that is processing transactions that existed in the input queue before the start checkpoint has encountered or a program scheduled by an unrecoverable message.)

P

Program Switch Send/Receive Processing

Q

Transmit Only Program Switch Processing

S

Send/Receive Processing

T

Transmit Only Processing

X

Conversational Program Switch, Send/Receive Processing

Y

Transmit Only Conversational Program Switch Processing
Time HHMMSST
Input queue time is from SMB enqueue to message schedule.
Time SSSST or OVRFLW (If the total seconds exceeds the field size, OVRFLW is printed).
If the wait-for-input (WFI) system option is used, the time processing field also includes the wait time between transactions.
Output queue time is from CNT enqueue to CNT GU.
Total Time is from SMB enqueue to CNT dequeue. The total time spans the complete transaction.