Interface Traces

When you submit a report request, the Interface generates calls to the IMS DBMS on your behalf. You can use the Interface trace facilities to view these calls and their results.

A trace is helpful for debugging a procedure or for Interface performance analysis. The FSTRACE, FSTRACE2, and FSTRACE4 facilities are easy to invoke and require no changes to either the Interface or user request. The trace facilities have no effect on how the Interface functions.

The Interface provides the following trace facilities:

FSTRACE captures or displays the PCB, the call parameters, and the SSA buffer prior to each DL/I call, and it shows the PCB, key feedback area, return code, and a dump of the I/O buffer contents after each DL/I call. FSTRACE Example, includes an example of FSTRACE output.

FSTRACE2 shows the Userid, Filename and return code used and returned by the exit.

FSTRACE4 captures or displays each SSA generated for a request. Chapter 4, Reporting Efficiencies, includes several examples of FSTRACE4 output.

In the DBCTL environment, FSTRACE4 also provides statistics about the number of calls, reads, enqueues, and buffers. FSTRACE4 Statistics in the DBCTL Environment, provides an example of the statistics generated in the DBCTL environment.

To activate one or both of the trace facilities, allocate the corresponding trace output as described in Allocating Interface Traces.

Note: FSTRACE, FSTRACE2 and FSTRACE4 are intended for use in query optimization and problem debugging. Do not write application programs that depend on the format or content of any trace, as these may change in later releases.

Top of page

Allocating Interface Traces

You can use FSTRACE, FSTRACE2, and FSTRACE4 in conjunction with all report requests. You can store trace output in a sequential dataset or display it online at the terminal. Use the system editor to view the file containing the trace information.

To capture trace data in a file, issue the appropriate statement from the FOCUS command level

{MVS|TSO} ALLOC F(ddname) DA('userid.ddname') SHR REU LRECL(80) RECFM(F)

DYNAM ALLOC FILE ddname DATASET userid.ddname -
	SHR REUSE LRECL 80 RECFM F

CMS FILEDEF ddname DISK ddname DATA A
    (LRECL 80 RECFM F

where:

ddname: Is FSTRACE, FSTRACE2, or FSTRACE4.

To display trace data online, specify the appropriate statement from the FOCUS command level:

{MVS|TSO} ALLOC F(ddname) DA(*) SHR REU

DYNAM ALLOC FILE ddname DA *

CMS FILEDEF ddname TERMINAL

where:

ddname: Is FSTRACE, FSTRACE2, or FSTRACE4.

Top of page

Disabling Interface Traces

To disable FSTRACE, FSTRACE2 or FSTRACE4, clear the associated allocation

{MVS|TSO} FREE F(ddname)

DYNAM FREE FILE ddname

CMS FILEDEF ddname CLEAR

where:

ddname: Is FSTRACE, FSTRACE2 or FSTRACE4.

Top of page

Batch Trace Allocation

In batch, you can write trace results to a sequential file, a partitioned dataset, or, as in the following sample allocation, to SYSOUT

//ddname   DD SYSOUT=*,DCB=BLKSIZE=80

where:

ddname: Is FSTRACE, FSTRACE2, or FSTRACE4.

The following example writes the trace results to an MVS sequential dataset

//FSBATCH EXEC PGM=FOCUS
//ddname  DD  DISP=(NEW,CATLG,KEEP),DSN=userid.ddname,
//            UNIT=SYSDA,VOL=SER=volid,SPACE=(TRK,(p,s)),
//            DCB=(LRECL=80,BLKSIZE=1600,RECFM=F)

where:

userid: Is the user ID.
ddname: Is FSTRACE, FSTRACE2, or FSTRACE4.
volid: Is the volume ID of the dataset that will receive the trace output.
p: Is the number of tracks in the primary space allocation.
s: Is the number of tracks in the secondary space allocation.

Top of page

FSTRACE Example

This TSO session traces the retrieval process for a report request. FSTRACE is allocated before the report request is issued; its results display online.

The request is as follows:

 >  > DYNAM ALLOC FILE FSTRACE DA *
 >  > SET IMS=NEW
 >  > TSO IMS SET IMSPZP 00
 >  > TSO IMS SET DBCTL ON
 >  > TSO IMS SET PSB FOCSD
 >  > TABLE FILE DI21PART
 > PRINT PARTKEY STANKEY
 > WHERE PARTKEY IN ('02AN960C10','02JAN1N976B')
 > END

A trace can produce extensive output; therefore, you may want to use a RECORDLIMIT test in your request to reduce the amount of redundant information you will have to examine.

The following annotated example illustrates FSTRACE results for the request. Because this particular request includes the SET commands that turn DBCTL on and select the PSB, the calls to initialize the DRA (Database Resource Adapter) and schedule the PSB are included in the trace.

Trace output is separated into sections for each call to DBCTL; dotted lines mark the beginning and end of every section. Each individual section is also separated into two parts. The top part depicts information that the Interface passes to DBCTL; the bottom part presents the results of the call. The numbers on the left refer to explanatory notes listed at the end of the trace.

   -------------------------Calling DBCTL------------------------------------
1. Function = Initialize DRA
   ImdSrv=5439070
   usid=USER1   ,sufx=00,susp=5486ad0,resm=5486af8,cntl=5486a28,tstx=0
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = Initialize DRA
2. ctok=1e8e8,retc=0,dbct=IMS3,usid=USER1  ,mint=0,maxt=0,timo=999
   --------------------------------------------------------------------------
   -------------------------Control Exit Info--------------------------------
   ImdSrv=5439070
   func=2,sfnc=0,retc=0,rcod=0
   dbct=IMS3,jobn=IMS     ,rslt=0,rgty= 2,mtcb=1,dsid=  62
   idtk=z::,.:9:,rsen=        ,jsid=      ,mxn2=0,min2=0,hit2=0,tim2=0,mxt2=0
   --------------------------------------------------------------------------
   -------------------------Calling DBCTL------------------------------------
3.  Function = Schedule PSB
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ttok=5456848,psb=FOCSD   ,wrth= 1,cflg= 0,alan= 2,stat=0
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = Schedule PSB
   retc=0,ctk2=5457aa8,pcbl=35cc0,fpcb=35ccc,iosz=600,plan= 6,mkey=33
   --------------------------------------------------------------------------
   ** Before IMS call
4. There are 4 args
   cmd is (GU  )
    PCB: DI21PART00  GO
5. ssa 1
   D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*
   C5E8407E 40F0F2C1 D5F9F6F0 C3F1F040      *EY = 02AN960C10 *
   40404040 40405D40                        *      )         *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f9e8,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=50
   --------------------------------------------------------------------------
   **   After IMS call .
6.  PCB: DI21PART01  GO
   feedback len is (17)
   feedback area:
   F0F2C1D5 F9F6F0C3 F1F04040 40404040      *02AN960C10      *
   40                                       *                *
7.   io buff:
   F0F2C1D5 F9F6F0C3 F1F04040 40404040      *02AN960C10      *
   40404040 40404040 4040E6C1 E2C8C5D9      *          WASHER*
   40404040 40404040 40404040 40404040      *                *
   40400000 00000000 00000000 00000000      *                *
   00000000 00000000 00000000 00000000      *                *
   ** Before IMS call 
8. There are 5 args
   cmd is (GU  )
    PCB: DI21PART01  GO
9.   ssa 1: PARTROOT*U
   ssa 2
   E2E3C1D5 C9D5C6D6 5C604040               *STANINFO*-      *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f710,alan= 2
   --------------------------------------------------------------------------   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=85
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART02  GO
   feedback len is (19)
   feedback area:
   F0F2C1D5 F9F6F0C3 F1F04040 40404040      *02AN960C10      *
   40F0F2                                   * 02             *
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F1F440 40404040 40F0F6C3      *200  14      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call 
10.There are 5 args
   cmd is (GN  )
    PCB: DI21PART02  GO
    ssa 1: PARTROOT*U
   ssa 2
   E2E3C1D5 C9D5C6D6 5C604040               *STANINFO*-      *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f710,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=0
   --------------------------------------------------------------------------
   ** After IMS call 
11. PCB: DI21PART01GEGO
   feedback len is (17)
   feedback area:
   F0F2C1D5 F9F6F0C3 F1F04040 40404040      *02AN960C10      *
   40                                       *                *
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F1F440 40404040 40F0F6C3      *200  14      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call **
   There are 4 args
   cmd is (GN  )
    PCB: DI21PART01GEGO
   ssa 1
   D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*
   C5E8407E 40F0F2C1 D5F9F6F0 C3F1F040      *EY = 02AN960C10 *
   40404040 40405D40                        *      )         *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f9e8,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=0
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART00GEGO
   feedback len is (0)
   feedback area:
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F1F440 40404040 40F0F6C3      *200  14      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call 
12.There are 4 args
   cmd is (GU  )
    PCB: DI21PART00GEGO
   ssa 1
   D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*
   C5E8407E 40F0F2D1 C1D5F1D5 F9F7F6C2      *EY = 02JAN1N976B*
   40404040 40405D40                        *      )         *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f9e8,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=50
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART01  GO
   feedback len is (17)
   feedback area:
   F0F2D1C1 D5F1D5F9 F7F6C240 40404040      *02JAN1N976B     *
   40                                       *                *
    io buff:
   F0F2D1C1 D5F1D5F9 F7F6C240 40404040      *02JAN1N976B     *
   40404040 40404040 4040C4C9 D6C4C540      *          DIODE *
   C3D6C4C5 60C14040 40404040 40404040      *CODE-A          *
   4040F040 40F1F440 40404040 40F0F6C3      *  0  14      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call **
   There are 5 args
   cmd is (GU  )
    PCB: DI21PART01  GO
    ssa 1: PARTROOT*U
   ssa 2
   E2E3C1D5 C9D5C6D6 5C604040               *STANINFO*-      *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f710,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=85
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART02  GO
   feedback len is (19)
   feedback area:
   F0F2D1C1 D5F1D5F9 F7F6C240 40404040      *02JAN1N976B     *
   40F0F2                                   * 02             *
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F7F240 40404040 40F0F6C3      *200  72      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call **
   There are 5 args
   cmd is (GN  )
    PCB: DI21PART02  GO
    ssa 1: PARTROOT*U
   ssa 2
   E2E3C1D5 C9D5C6D6 5C604040               *STANINFO*-      *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f710,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=0
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART01GEGO
   feedback len is (17)
   feedback area:
   F0F2D1C1 D5F1D5F9 F7F6C240 40404040      *02JAN1N976B     *
   40                                       *                *
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F7F240 40404040 40F0F6C3      *200  72      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
   ** Before IMS call **
   There are 4 args
   cmd is (GN  )
    PCB: DI21PART01GEGO
   ssa 1
   D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*
   C5E8407E 40F0F2D1 C1D5F1D5 F9F7F6C2      *EY = 02JAN1N976B*
   40404040 40405D40                        *      )         *
   -------------------------Calling DBCTL------------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   ctok=1e8e8,ctk2=5457aa8,ttok=5456848,clst=1f9e8,alan= 2
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = DLI request
   ImdSrv=5439070, ImdUsr=5456848
   retc=0,segl=0
   --------------------------------------------------------------------------
   ** After IMS call **
    PCB: DI21PART00GEGO
   feedback len is (0)
   feedback area:
    io buff:
   F0F24040 40404040 40404040 40404040      *02              *
   4040F7F4 F2404040 40404040 40404040      *  742           *
   40404040 40404040 40404040 404040F1      *               1*
   F2F0F040 40F7F240 40404040 40F0F6C3      *200  72      06C*
   40404040 4040F0F6 C3404040 40404040      *      06C       *
  	 -------------------------Calling DBCTL------------------------------------
13.Function = Prepare for Commit                                             
   ImdSrv=7e080c8, ImdUsr=7e18578                                            
   ctok=21840,ctk2=7ebb530,ttok=7e18578,stcd=7d52fb0                         
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = Prepare for Commit                                             
   retc=0,stcd=3,                                                            
   --------------------------------------------------------------------------
   -------------------------Calling DBCTL------------------------------------
   Function = Commit - Terminate                                             
   ImdSrv=7e080c8, ImdUsr=7e18578                                            
   ctok=21840,ctk2=7ebb530,ttok=7e18578,rtok=c4d6c3e2                        
   --------------------------------------------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = Commit - Terminate                                             
   retc=0                                                                    
   --------------------------------------------------------------------------
   -------------------------Calling DBCTL------------------------------------
   Function = Terminate thread                                               
   ImdSrv=7e080c8, ImdUsr=7e18578                                            
   ctok=21840,ctk2=7ebb530,ttok=7e18578--------------------------------------
   -------------------------Back from DBCTL----------------------------------
   Function = Terminate thread                                               
   retc=0                                                                    
   --------------------------------------------------------------------------
    NUMBER OF RECORDS IN TABLE=        2  LINES=      2
  
    PAUSE.. PLEASE ISSUE CARRIAGE RETURN WHEN READY

The trace shows the following:

The call to initialize the DRA; the Interface passes both the userid (USER1) and the suffix for the DRA Startup Table (00) to DBCTL.

DBCTL sends back a return code (retc) of 0 signifying that the DRA was initialized with no problem. A non-zero return code at this stage indicates a need to execute the IMDTST JCL described in Installation Instructions.
The call to schedule the PSB; the Interface passes the name of the PSB, FOCSD, to DBCTL. The return code of 0 after the call indicates that the PSB was scheduled with no problem.
The number of arguments for the first DL/I call to IMS. Each DL/I call requires the following arguments: the function to be performed (GU or GN), the PCB, an I/O area, and, if relevant, one or more SSAs. The number of SSAs depends on the nature of the request and the number of segments involved.

This call is a GU call. The PCB contains the database name, DI21PART, and the PROCOPT, GO.

The SSA for this call. There is one SSA to locate the root segment with PARTKEY=02AN960C10. The trace provides the SSA in the form of a dump of the SSA buffer.

A dump has a left side and a right side. The left side shows the hexadecimal values in the memory locations. The right side, delimited by *'s, contains the corresponding alphanumeric characters. Since not all hexadecimal values represent printable alphanumeric characters, those parts of the dump that correspond to non-printable characters display as blanks on the right side. In particular, if a comparison value in an SSA is a packed number, it displays as blank on the right-hand side of the dump.

In this case, PARTKEY is an alphanumeric field, so the comparison value, 02AN960C10, is also alphanumeric and displays in the dump. The Interface constructs a qualified SSA that includes the segment name, PARTROOT, and the logical expression, PARTKEY=02AN960C10.

When there are no selection criteria for a segment, the Interface constructs an SSA that contains only the segment name.

The PCB after the IMS call. The segment level (01) of the retrieved segment is now in the PCB, and the status code (2 blanks) indicates a successful retrieval. The key feedback area is also part of the PCB and contains the concatenated key of each segment in the hierarchical path to the retrieved segment. (Since only the root segment was retrieved in this call, the key feedback area contains the retrieved PARTKEY value.)
A dump of the I/O buffer after the DL/I call. This buffer contains the retrieved segment. For instructions about reading the dump, see item 5.
The start of the next call to IMS, a GU call to retrieve the first child of the PARTROOT segment retrieved in the previous call. This call has five arguments because there are now two SSAs: one for each segment.
The SSAs for this call. The first SSA uses the U command code to stay within the chain of children of the previously-retrieved PARTROOT segment.

The second SSA is for the STANINFO segment (the FOCUS request prints the STANKEY field from this segment). Since the request contains no selection criteria on this segment, the SSA is unqualified and contains only the segment name. This call retrieves a STANINFO segment with STANKEY = 02 (see the feedback area and I/O buffer).

The third DL/I call, a GN call to retrieve the next child of the previously-retrieved PARTROOT segment. The SSAs are the same as those in item 9.
The PCB after the third call to IMS. The GE status code in the PCB indicates that no segment was found that satisfied the search criteria.
A GU call to locate a PARTROOT segment with PARTKEY=02JAN1N976B. The entire sequence of calls described in the previous items repeats for this value of PARTKEY.
The cleanup at the end of the request. The cleanup process terminates the DBCTL threads and unschedules the PSB.

The following report is generated:

  PAGE     1


  PARTKEY            STANKEY
  -------            -------
  02AN960C10         02
  02JAN1N976B        02

Top of page

FSTRACE4 Statistics in the DBCTL Environment

When you allocate FSTRACE4 in the DBCTL environment, the trace provides statistics about the number of calls made, enqueues, waits, and buffers. The following example illustrates FSTRACE4 results in this environment:

 >  > DYNAM ALLOC FILE FSTRACE4 DA * 
 >  > TABLE FILE DI21PART
 > PRINT PARTKEY STANKEY
 > WHERE PARTKEY IN ('01AN960C10','02JAN1N976B')
 > END

The resulting trace provides the SSA buffer and the UOR statistics:

  set up SSA-Q:                                                            
D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*                
C5E8407E 40F0F1C1 D5F9F6F0 C3F1F040      *EY = 01AN960C10 *                
40404040 40405D40                        *      )         *                
  set up SSA-Q:                                                            
D7C1D9E3 D9D6D6E3 5C604DD7 C1D9E3D2      *PARTROOT*-(PARTK*                
C5E8407E 40F0F2D1 C1D5F1D5 F9F7F6C2      *EY = 02JAN1N976B*                
40404040 40405D40                        *      )         *                
  set up SSA-Q:                                                            
E2E3C1D5 C9D5C6D6 5C604040               *STANINFO*-      *                
 -------------------------UOR Statistics-----------------------------------
 GU calls=3,GN calls=2,GNP calls=0,GHU calls=0,GHN calls=0,GHNP calls=0,   
 ISRT calls=0,DLET calls=0,REPL calls=0,Total DLI calls=5,                  
 Test ENQ=0,Waits for Test ENQ=0,Test DEQ=0,Update ENQ=0,Waits for Updt ENQ=0,U
p                                                                          
 Exclusive ENQ=0,Waits on Exclusive ENQ=0,Exclusive DEQ=0,                 
 DEDB Calls=0,DEDB Reads=0,Overflow Buffers Used=0,UOW Contentions=0,      
 Waits for DEDB Buffers=0,Schedule Seq Number=998,                         
 Elapsed UOR CPUTIME (Timer units)=209.                                    
 -------------------------------------------------------------------------

If your request seems to take a long time, you may want to allocate FSTRACE4 to see if any of the numbers are very high. Enqueues become a factor depending on the PROCOPT you use.

Information Builders