Adapter Traces

In this section:

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

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

The adapter provides the following trace facilities:

To activate one or both of the trace facilities, allocate the corresponding trace output as described in Allocating Adapter 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

x
Allocating Adapter 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)

or

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

or

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

or

DYNAM ALLOC FILE ddname DA *

or

CMS FILEDEF ddname TERMINAL

where:

ddname

Is FSTRACE, FSTRACE2, or FSTRACE4.


Top of page

x
Disabling Adapter Traces

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

{MVS|TSO} FREE F(ddname)

or

DYNAM FREE FILE ddname 

or

CMS FILEDEF ddname CLEAR

where:

ddname

Is FSTRACE, FSTRACE2 or FSTRACE4.


Top of page

x
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

x
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 adapter 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:

  1. The call to initialize the DRA. The adapter passes both the userid (USER1) and the suffix for the DRA Startup Table (00) to DBCTL.
  2. 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.
  3. The call to schedule the PSB. The adapter 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.
  4. 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.

  5. 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 trace. The adapter 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 adapter constructs an SSA that contains only the segment name.

  6. 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.)
  7. 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.
  8. 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.
  9. 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).

  10. 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.
  11. 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.
  12. 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.
  13. 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

x
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