Narrowing down GTF trace output

The General Trace Facility (GTF) in MVS is useful for identifying problems, but narrowing down GTF trace data can be daunting. This tip offers a how-to on narrowing down GTF trace output to simplify debugging.

MVS' General Trace Facility (GTF) is one of those tools that makes you glad to work on the mainframe. When started, a GTF trace can record all sorts of system events and provide detailed diagnostic data for those hard-to-find bugs. Of course, the formatted output is prodigious, which makes gleaning the nuggets of information necessary to debug the problem harder than finding a liquor store in Waco. However, a little REXX combined with a less-traditional debugging tool can help discover the gold from a GTF trace.

GTF traces for SVCs
One useful GTF feature is the ability to capture supervisor call (SVC) instructions that problem programs use to access system services. Imagine, for instance, we have response time problems because we suspect an application is issuing operating system waits instead of using CICS' application programming interface (API). A GTF trace for wait SVCs (SVC 1) will collect, among other things, the instruction addresses of the service call. The instruction addresses, combined with a dump of the region, can quickly pinpoint the program issuing the non-CICS waits.

Below are some sample parameters for GTF. Note that years ago GTF got its parameters from the console. You can see this historical context below, where "prompting" options (the ones that end in "P") do little else except tell GTF to expect the actual parameters later in the input stream. Thus, the SVCP parameter points to the SVC option listing the SVC numbers to be traced. Similarly, JOBNAMEP refers to JOBNAME to be traced.


Formatting the GTF trace
IBM's Interactive Problem Control System (IPCS) can format the raw GTF trace data. Pasted below is some sample output, where you can see lots of useful information about the circumstances under which something issued the WAIT.

**** GTF TRACING ENVIRONMENT ****                                                             
     Release: SP7.0.9   FMID: HBB7740   System name: SYSP                                                   
     CPU Model: 2097  Version: 00  Serial no. 015EFF                                                        
SVC..... 001  ASCB.... 00FC0880 CPU..... 0002     JOBNAME. CICSPROD OLD-PSW. 078D0001 95113178         
              TCB..... 00A98E00 MODN.... DFHKETCB R15... F918ABD8 R0... 00000001 R1... 1E19D328
              PLIST... 1E19D328                                                                        
          GMT-01/27/2010 18:27:46.321507  LOC-01/27/2010 12:27:46.321507                               
 SVC..... 001 ASCB.... 00FC0880 CPU..... 0001     JOBNAME. CICSPROD OLD-PSW. 078D0001 95112F3C         
              TCB..... 00AF8680 MODN.... DFHKETCB R15... BE06CECE R0... 00000001 R1... EA99C000
              PLIST... 15703128 000408B8 0022AB64 00054C8C 80054BE4                                    
          GMT-01/27/2010 18:27:46.321775  LOC-01/27/2010 12:27:46.321775  

Now we have a great pile of diagnostic information consisting of a dump and a GTF trace. The challenge is to separate legitimate waits executed by the CICS system code from the application issued SVCs. The brute force method would dictate going through each trace entry and matching Program Status Words (PSWs) with load modules in the CICS dump. That might take a while.

Boiling down GTF trace data with REXX and Excel
Fortunately, a little REXX that can convert GTF trace output into a command separated value (CSV) file suitable for importing into Excel. I included an example REXX program below.

/*  REXX  */          
parse arg input                                                                 
"del 'user01.gtfsvc.csv'"                    /* Delete and reallocate output file  */
"alloc fi(csvout) da('user01.gtfsvc.csv') unit(sysda) space(15 15)",
      "track new catalog lrecl(60) blksize(18000) recfm(f b) release"                                                                                
csvout.1 = "SVC,Job Name,PSW,TCB"            /*  Write column headers  */
"execio 1 diskw csvout (stem csvout."                                           
"EXECIO 1 DISKR gtfin (stem gtfin."          /*  Top of input loop  */
do while(rc = 0)                                                                
   if index(gtfin.1, 'SVC.....') > 0 then,   /*  Beginning of an entry */                                     
         firstWord = 2                                                          
         if word(gtfin.1, 1) = '1' then,     /*  Deal with page ejects */   
               firstWord = 3                                                    
         svc = word(gtfin.1, firstWord)      /*  Get SVC, job name and PSW  */
         jobname = word(gtfin.1, firstWord+6)                                   
         psw = word(gtfin.1, firstWord + 8) || ' ' || word(gtfin.1, firstWord+9)
         "EXECIO 1 DISKR gtfin (stem gtfin." /*  Get next line for TCB address  */                                    
         if word(gtfin.1, 1) = '1' then,     /*  Again with the page ejects?  */                                        
               tcb = word(gtfin.1, 3)                                           
               tcb = word(gtfin.1, 2)                                           
         csvout.1 = svc || ',' || jobname || ',' || psw || ',' tcb              
         "execio 1 diskw csvout (stem csvout." /*  Build and write output  */
   "EXECIO 1 DISKR gtfin (stem gtfin."         /*  Get next line  */
queue                                          /*  It's all over, go home  */
address tso                                                                     
"execio * diskr gtfin (finis)"                                                  
"execio * diskW csvout (finis)"                                                 
"free fi(csvout)" 

Disclaimer: This is "fair weather" sample code that may or may not work with your GTF report.

This script's one parameter is the name of a DD statement pointing to a dataset containing the GTF report. It writes the output CSV file to dataset userid.GTFSVC.CSV. The CSV output contains four columns, which include the SVC number, the job name, the PSW of the instruction that issued the SVC and the Task Control Block (TCB) of the thread. It writes the header labels as the first row in the CSV file.

Now it becomes a simple matter to import the CSV file into Excel. The resulting spreadsheet looks like this:

Click to enlarge.

Auto-filtering the spreadsheet gives us the ability to get a summary list of the columns. The auto-filter option appears in the Excel "Data" pull-down menu.

Once the spreadsheet is filtered, we can do things like click on the PSW header button and get a summary list of addresses that issued the wait SVC.

Click to enlarge.

Now, instead of wading through hundreds of trace entries, we have a list of five PSWs to check against the dump.

More ways to analyze GTF trace data
When I think of debugging, Excel doesn't usually spring to mind. However, its data analysis abilities make it a good secondary tool to make sense out of the blizzard of data produced by MVS. Other enhancements to this REXX might include capturing the trace timestamp or parameter list. The same principle may also be applied to other forms of GTF trace output.

ABOUT THE AUTHOR: For 24 years, Robert Crawford has worked off and on as a CICS systems programmer. He is experienced in debugging and tuning applications and has written in COBOL, Assembler and C++ using VSAM, DLI and DB2.

What did you think of this feature? Write to SearchDataCenter.com's Matt Stansberry about your data center concerns at [email protected].

Dig Deeper on IBM system z and mainframe systems