Control block trace

Figure 1 is an example of SYSOMVS component trace records requested with OPTIONS(CBTR(PPRP,0,4)) to trace a four byte field at offset zero in the PPRP control block. The trace data was then formatted with the CTRACE COMP(SYSOMVS) subcommand:

Figure 1. Control block trace output
       SY1 SYSCALL   0F080001  20:06:58.662146  STANDARD SYSCALL ENTRY TRACE
                                                                           
        ASID..0020      USERID....IBMUSER   STACK@....25D58010                 
        TCB...008BF088  EUID......00000000  SYSCALL...00000019                 
        +0000  00000019  00000000  D1C3E2C5  8C0000F4  | ........JCSE...4 |     
        +0010  0000000C  00000000  80D1AE06  25D596F4  | .........J...No4 |     
        +0020  25D596E4  00000085  00000000  7F5FF0A8  | .NoU...e...."¬0y |     
        +0030  00000006  2501BB50  00D1AFA4  7F5FF0E8  | .......&.J.u"¬0Y |     
        +0040  7F5FF0CC  7F5FF0D0  FF5FF0D4            | "¬0."¬0}.¬0M     |     
        +0050  D7D7D9D7  00000004  D7D7D9D7 00000000    PPRP.........PPRP

      	SY1  SYSCALL   0F080002  20:06:58.662171  STANDARD SYSCALL EXIT TRACE
                                                                          
        ASID..0020      USERID....IBMUSER   STACK@....25D58010                
        TCB...008BF088  EUID......00000000  SYSCALL...00000019                
        +0000  00000019  00000000  D1C3E2C5  8C000000  | ........JCSE.... |    
        +0010  0000000A  00000000  00000000  00000002  | ................ |  
        +0020  00000002  D7D7D9D7  00000004  D7D7D9D7   PPRP..........PPRP
               00000000

Figure 2 is an example of SYSOMVS component trace records formatted with the CTRACE COMP(SYSOMVS) SHORT subcommand.

Figure 2. SYSOMVS component trace formatted with CTRACE COMP(SYSOMVS) SHORT
 COMPONENT TRACE SHORT FORMAT
 COMP(SYSOMVS)
 **** 06/17/92

 MNEMONIC  ENTRY ID    TIME STAMP     DESCRIPTION
 --------  --------  ---------------  -----------

 SYSCALL   0F080002  22:02:42.314264  STANDARD SYSCALL EXIT TRACE
 SYSCALL   0F080001  22:02:42.821156  STANDARD SYSCALL ENTRY TRACE
 PROCESS   0B080007  22:02:42.821219  PROCESS LATCH OBTAIN
 PROCESS   0B08000A  22:02:42.821256  PROCESS LATCH-ON THE WAY OUT
 FILE      05700103  22:02:42.821324  TRACE CALL TO VN_RDWR
 CHARS     05A90503  22:02:42.821398  TRACE CHARSPEC CALL TO DEVICE DR
 PROCESS   0B080008  22:02:42.821452  PROCESS LATCH RELEASE REQUEST
 PROCESS   0B08000A  22:02:42.821472  PROCESS LATCH-ON THE WAY OUT
 DEVPTY    0223E005  22:02:42.821530  MASTER READ BEGIN
 DEVPTY    0223E008  22:02:42.821566  MASTER READ END
 PROCESS   0B080007  22:02:42.822182  PROCESS LATCH OBTAIN
 PROCESS   0B08000A  22:02:42.822206  PROCESS LATCH-ON THE WAY OUT
 CHARS     05A90603  22:02:42.822253  TRACE DEVICE DRIVER READ RETURN
 FILE      05700203  22:02:42.822506  TRACE RETURN FROM VN_RDWR

The output from a SYSOMVS trace using the SCCOUNTS option has 2 formats, shown in Figure 3 and Figure 4.

Figure 3. SCCOUNT Function Displaying SYSCALL Frequency
SYSCALL#     SYSCALL NAME      COUNT      FREQUENCY/SEC
--------     ------------      -----      -------------
    F        BPX1CHO            5000           nnn
   2F        BPX1STA             150           nnn

Figure 3 is sorted by frequency, with the highest values appearing at the top of the list. SYSCALL# is the hexadecimal number of the syscall. FREQUENCY/SEC is the number of times the syscall has been invoked within the interval.

Figure 4. SCCOUNT Function Displaying Function Code Frequency
 FuncCode    FuncCode Name     Count      Functions/Sec
 --------    ------------      -----      -------------
 00001001    MntCatchup         76           0.0593
 00001010    GetPathName        60           0.0468
 00000012    UnQuiesce          38           0.0296

Figure 4 is sorted by frequency, with the highest values appearing at the top of the list. FuncCode is the hexadecimal number of the function code. Functions/Sec is the number of times the function code has been invoked within the interval.

The output from a SYSOMVS trace using the KERNINFO option is shown in Figure 5. The syscall function name (FCN) and the process ID (PID) are shown on the first line of the trace entry.

Figure 5. CTRACE COMP(SYSOMVS) FULL OPTIONS((KERNINFO))
 FCN...open          SYSCALL...BPX1OPN  PID...00010006  MODULE...BPXJCPC   
 SY1       SYSCALL   0F080001  17:34:03.106875  STANDARD SYSCALL ENTRY TRACE
                                                                            
 	   ASID..0020      USERID....MEGA      STACK@....26E09068       			 	   
      TCB...008C1470  EUID......00000000  PID.......00010006            
    +0000  00000026  00000000  D1C3E2C5  8C000048  | ........JCSE.... |     
    +0010  8002000E  00000000  863CED16  02290200  | ........f....... |     
    +0020  60000000  269D8CA0  00000000  25B36828  | -............... |     
    +0030  00000007  00000010  61A39497  614BA288  | ......../tmp/.sh |     
    +0040  6D8889A2  A39699A8  00000000  0000048B  | _history........ |     
    +0050  00000180  FFFFFFFF  0000006F  5B4C0002  | ...........?$<.. |     
    +0060  00000000  00000000  00000000  00000000  | ................ |     
    +0070  00000000  00000000  00000000  00000000  | ................ |     
    +0080  00000000  00000000  00000000            | ............     |     
   FCN...open          SYSCALL...BPX1OPN  PID...00010006  MODULE...BPXJCPC   
 SY1       SYSCALL   0F080002  17:34:03.106876  STANDARD SYSCALL EXIT TRACE 
                                                                            
      	   ASID..0020      USERID....MEGA      STACK@....26E09068       			 	   
           TCB...008C1470  EUID......00000000  PID.......00010006                       
    +0000  00000026  00000000  D1C3E2C5  8C000000  | ........JCSE.... |     
    +0010  8002000B  00000000  FFFFFFFF  0000006F  | ...............? |     
    +0020  5B4C0002
Parent topic: Output from a SYSOMVS trace