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.

Requires Free Membership to View

Similarly, JOBNAMEP refers to JOBNAME to be traced.

 TRACE=SVCP,JOBNAMEP
SVC=(1) JOBNAME=(CICSPROD),END

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 */                                     
      do                                                                        
         firstWord = 2                                                          
         if word(gtfin.1, 1) = '1' then,     /*  Deal with page ejects */   
            do                                                                  
               firstWord = 3                                                    
            end                                                                 
         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?  */                                        
            do                                                                  
               tcb = word(gtfin.1, 3)                                           
            end                                                                 
         else,                                                                  
            do                                                                  
               tcb = word(gtfin.1, 2)                                           
            end                                                                 
         csvout.1 = svc || ',' || jobname || ',' || psw || ',' tcb              
         "execio 1 diskw csvout (stem csvout." /*  Build and write output  */
      end                                                                       
   "EXECIO 1 DISKR gtfin (stem gtfin."         /*  Get next line  */
end                                                                             
                                                                                
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 mstansberry@techtarget.com.

This was first published in March 2010

There are Comments. Add yours.

 
TIP: Want to include a code block in your comment? Use <pre> or <code> tags around the desired text. Ex: <code>insert code</code>

REGISTER or login:

Forgot Password?
By submitting you agree to receive email from TechTarget and its partners. If you reside outside of the United States, you consent to having your personal data transferred to and processed in the United States. Privacy
Sort by: OldestNewest

Forgot Password?

No problem! Submit your e-mail address below. We'll send you an email containing your password.

Your password has been sent to:

Disclaimer: Our Tips Exchange is a forum for you to share technical advice and expertise with your peers and to learn from other enterprise IT professionals. TechTarget provides the infrastructure to facilitate this sharing of information. However, we cannot guarantee the accuracy or validity of the material submitted. You agree that your use of the Ask The Expert services and your reliance on any questions, answers, information or other materials received through this Web site is at your own risk.