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.
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:
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.
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 firstname.lastname@example.org.
This was first published in March 2010