Transcript Performance Tuning Mainframe Applications at Westpac

AMPDEV
IMSTRACE V4.3
Tony Shediak
Ampdev P/L
www.Ampdev.com
Overview
The Ampdev IMSTRACE utility intercepts all DL/I calls issued by a
Load Module and reports:
• Function issued
• Segment Search Arguments
• Status Code
• Response Time
• Module Offset
• Module name and call chain
• Key feedback Area
• IMS/DC messages
• Segment I/O Area Contents
 WITHOUT re-compilation.
IMSTRACE works only off the executable load
module.
Use it to • Track down bugs in the code – as you can see the DL/I
calls, SSAs, and the resulting Status Code
• Look at performance – as you can see the Response Time
of each call
• Understand what the program is doing – as you can see
each DL/I call in the sequence it was issued
• Analyse the correctness and the quality of the code
- as you can see how each database is being manipulated
by the program and the navigation through each segment
• View input/output IMS messages – as you can see each
input TRAN and OUTPUT message processed
• View Segment I/O Content to ensure correctness of data
• ALL this WITHOUT Re-compilation
Use it to • Locating the Message Processing Region where your program
was SCHEDULED when executing under an IMSPLEX running
multiple IMS systems across a SYSPLEX.
It can be difficult for programmers to find their program output
within a IMSPLEX (IMS Shared Q) environment as a
transaction can process in multiple regions across multiple
LPARS.
When IMSTRACE is enabled for a IMS/TM Program, the
LOCATE option (IMSTRACE ISPF main menu option 4)
will list the last 12 SCHEDULES of the program within the
IMSPLEX and will identify the Message Region and IMS
System that executed the program.
• ALL this WITHOUT Re-compilation
ISPF Panel - Main
Attach Trace
Take it from this Library
Attach Trace and put new Load in
this Library
Load Module Name
SET Trace Options
SET Trace Options
Segment I/O Trace
Path I/O Trace
For database DBCAR display the I/O area when the program issues
a PATH call (D command code) specifying the segments
COMPANY, MODEL and OPTION.
Same for DB512 with segments SG19480 and SG19481.
The start and length dictate which portions of the I/O area to
display
SYNC with LPARs
Batch job will automatically be
submitted on LPAR 296A every
time the run-time options are
updated on the current LPAR 292C
to Synchronise options across both
LPARs
Detach Trace
Take it from this Library
Remove Trace and put new Load in
this Library
Load Module Name
LOCATE Output
Shows Last 12 SCHEDULEs of this
program across the IMSPLEX and
identifies the IMS System and
REGION which executed your
program.
Selecting the REGION will take
you to SDSF where you can view
the trace output within that
REGION job output – DD
$TRGOUT
LOCATE Output
LOCATE Output
Trace output Dynamically allocated
in MPR under $TRGOUT
Trace Output $TRGOUT
For any BATCH Job or IMS/TM
Message Processing Region, the trace
output will be DYNAMICALLY
allocated under DDname $TRGOUT.
For CICS the output is stored in a
dataset and can be extracted as
required.
A – AIBTDLI call
Module issuing call – and offset of call within code
Response Time
Call details:
PCB Name (if AIB)
Call Number
Function
Database
Status Code “( )”
SSA or sub-function
2nd PCB for this DB
SSA key value
shown in hex
if unprintable
SSA values
Enter subroutine PGET32MX called
from PGETTS1
DL/I call was issued at offset 0005DC within
module
IMSC2D
which was called from IMSOP
which was called from IMSC1
which was called from IMSMC1
Segment I/O Trace for PATH SG19480
and SG19481 starting at 1 for 63 and
64 for 65
Show IMS/DC input and output messages
including length (LL) and reserved area (ZZ)
Show Key feedback area
including Segment Level (SL),
Name (SN) and concatenated
key (KFBA)
New in V4.3 – Loadlib Trace
Steplib/Joblib DSN which
contains the executing load
module
Options
•
Options can be set via ISPF Panels
•
Can also be set Via Batch Job with Input cards, e.g:
PROGRAM = IMSCASE2
TRACE_KFBA = Y
TRACE_MSG = Y
TRACE_IO_DB = DBCAR
TRACE_IO_SEG = COMPANY
TRACE_IO_START = 1
TRACE_IO_LEN = 12
TRACE_IO_DB = DBACCT
TRACE_IO_SEG = ACCT
TRACE_IO_SEG = ADDR
TRACE_IO_START = 1
TRACE_IO_LEN = 30
TRACE_IO_START = 45
TRACE_IO_LEN = 20
Show I/O Area for Segment
COMPANY of DBCAR starting at
position 1 for a length of 12
Show I/O Area for PATH of
Segments ACCT and ADDR of
DBACCT starting at position 1 for
a length of 30 and from position
45 for a length of 20
Options
•
TRACE_LIMIT = nnnnnnnnn
where nnnnnnnnn = max number of calls to trace for this program
Default is 30000
•
TRACE_AFTER_CNT = nnnnnnnnn
where nnnnnnnnn = number of calls to skip before tracing
Default is 0
•
TRACE_KFBA = Y or N
show the Key-feedback information, Segment name and Segment level per
DB call. For example an additional 2 lines per DB call might be:
+ SL<02> SN<ACCOUNT>
+ KFBA<X6797890234
>
EFFFFFFFFFF9346
76797890234183C
If the Key-feedback contains unprintable characters then it will also be
displayed in hex
Default is N
Options
•
TRACE_DYNAMIC = Y or N
allow run-time options to be changed whilst the programming is running.
Normally options are applied at program startup, but with
TRACE_DYNAMIC = Y options will be applied EVERY time a DL/I call
is intercepted by IMSTRACE.
This is useful for long-running or pre-loaded programs where you want to
turn the trace ON or OFF dynamically (using TRACE_ON = Y/N) or alter
any other option on the fly.
There is a slight overhead per DL/I call to support this option
Default is N
•
TRACE_ON = Y or N
turn IMSTRACE On or Off for this program. So even a program with the
trace attached can be run with the trace enabled/disabled as required
Default is Y
Options
•
TRACE_IN = Y or N
display DL/I call on INPUT (before passing to the DL/I routine) and
OUTPUT (after returning from DL/I). Without this option enabled the DL/I
call is displayed on return from the DL/I routine.
This is useful when diagnosing an ABEND (e.g. U476 or U200) within a
DL/I call, as IMSTRACE will tell you which call caused the abend by the
absence of the output line.
Below is an example of the input and output display of a DL/I call
C SUB001
C OUTPUT==>
Default is N
0001E8
1 GU
0.000025 0001E8
1 GU
????????(??) ACCTSEG *P--(ACCTNUM ..
BRNCHSEG*--DB457
( ) ACCTSEG *P--(ACCTNUM ..
BRNCHSEG*---
Options
•
TRACE_MSG = Y or N
display IMS/DC messages read or inserted by the program including the
length value (LL) and reserved area (ZZ).
For example:
C PGM001
+ LL<
000108
26> ZZ<
1 GU
0> MSG<TRAN1
LT0012
A12746654890YY>
Default is N
•
TRACE_DB = xxxxxxxx
where xxxxxxxx = DB name to be traced. With this enabled only the
database calls referencing THIS DB name will be traced. This can be useful
when focusing on a specific database and how it is used.
A maximum of 3 TRACE_DB statements can be specified per program
Default is trace everything
Options
•
TRACE_IO_DB= xxxxxxxx
where xxxxxxxx = DB name for which Segment I/O will be traced
•
TRACE_IO_SEG = xxxxxxxx
where xxxxxxxx = Segment Name for which I/O area will be traced
for database defined with TRACE_IO_DB
•
TRACE_IO_START = nnnnn
where nnnnn = starting position within I/O Area to be displayed
•
TRACE_IO_LEN = nnnnn
where nnnnn = Length from Start within I/O Area to be displayed
For Example Show DBCAR segment COMPANY from 1 for 12 bytes :
A <==<CASE2>
A IMSC2
0.740731 00040C
DB=DBCAR
SEG I/O=|COMPANY |
DATA (
1, 12)
----+----1-HOLDEN
CDDCCD444444
863455000000
1 GU
DBCAR
(
) COMPANY *--
Can be Enabled via Batch
Set program name,
Set program name,
input/output Loadlib
input/output Loadlib
And LKD53 is created in
the TEST load lib with
the IMSTRACE enabled
What about CICS?
• CICS feature is available as an option to support IMS programs
(call level only) running under the CICS environment.
• When enabled for a CICS program the IMSTRACE will direct
all output to a VSAM dataset (RRDS format). The trace
report can then be requested using a simple one step reporting
Job. As CICS regions process many different transactions, the
reporting job allows trace information to be selected by any/all
of:
- Program name
- Transaction name
- User
- Terminal
- From Date/Time
- To Date/Time
What about CICS?
• Trace is enabled via ISPF Panel or batch job, just like non-CICS.
• Trace options set the same way as non-CICS, via ISPF Panel or
batch job . Obviously TRACE_MSG not allowed in CICS.
• Trace output looks the same, and UIB codes shown for PCB:
*****************************************************************************************
* USER<XMSIIP > TRAN<CECI> TERM<1CGQ>
PGM<PGGSFQ > DATE<2005/02/16> TIME<..
*****************************************************************************************
C TS001
0.071616 0005A2
1 PCB PGED011
UIBFCTR(00) UIBDLTR(00)
C CASE2
0.000045 0008C4
2 GU
DBCAR
( ) COMPANY *-.
A <==<IMSC1>==<CASE2>
A IMSC2
0.000047 00040C
6 GU
DBCAR
( ) COMPANY *-A CASE2
0.000049 00098E
7 GN
DBCAR
( ) COMPANY *--(MANUF
=
A
MODEL
*-A CASE2
0.000012 000A26
8 GNP DBCAR
(GE) OPTION *-A CASE2
0.000014 000B06
9 GNP DBCAR
(GE) COLOUR *-A CASE2
0.000040 000BDE
10 GN
DBCAR
( ) COMPANY *--(MANUF
=
A
MODEL
*-.
.
A IMSP1
0.000194 0002CC
12 GU
DBCAR
(AJ) COMPANY *--(MANUF=XXXX)
.
C TS001
0.008555 000870
14 TERM
Extract CICS Report
Extract Trace Records
depending on selection
criteria
Westpac usage - Analysis
•
Help analyse program function, especially within complex programs. This
usage was extensive within the “DECAP Project” where old CAP/COBOL
code was being rewritten to standard COBOL. The process that was
followed was to IMSTRACE the old load, run the relevant test cases, and
capture the trace output. This was used as part of the analysis phase.
When we see that the CAP/COBOL code generated was full of calls like:
CALL "CBLTDLI" USING DP003-PARMCOUNT
DP003-FUNCTION
DE053A-DBPCB
DILGDATA-WORK
DP003-SSA1
DP003-SSA2
DP003-SSA3
DP003-SSA4
DP003-SSA5
DP003-SSA6
You can appreciate the complexity. In addition to this, the project team
significantly improved the performance of each program by removing
redundant/repeated calls which they could easily see in the IMSTRACE
output.
Westpac usage - Analysis
•
For example:
.. 18
.
.
.. 57
.
.
.. 78
.
.
.. 112
.
•
GU DE018 ( ) SG22900 *P--(GR30002 EQM037120122060)
GU DE018 ( ) SG22900 *P--(GR30002 EQM037120122060)
GU DE018 ( ) SG22900 *P--(GR30002 EQM037120122060)
GU DE018 ( ) SG22900 *P--(GR30002 EQM037120122060)
In many cases the new code (Decapped code) achieved a reduction in the
number of DL/I calls by 40 – 50%. This combined with efficient navigation
through each database achieved significant performance improvements.
Westpac usage –
Testing/Debugging/Training
P PGHB04A
0.000059 000212
1 GU
JL979 (
)
A <==<B000_RETR_DB639_CNTLFLD>==<AOMS0F>==<READ_TRADING_BANK>==<PGHB04C>==<PGHB04A>
A AOMD6C
0.000005 00012A
2 INQY DB639 (
) FIND
A AOMD6C
0.000098 000168
3 GU
) SG13259 *---(EL24332 EQIOU1)
DB639 (
DB639
A<==<AOMD1D1>==<AOMS0F>==<READ_TRADING_BANK>==<PGHB04C>==<PGHB04A>
A UTDBMPB
0.000066 0009F6
4 GU
DB039 (
) SG01140 *---(EL01140 = IQTDB1TB)
SG01141 *---
A<==<AOM3D>==<AOMG2L>==<AOMS0F>==<READ_TRADING_BANK>==<PGHB04C>==<PGHB04A>
A A000_RETR_DE039_ALL
0.009733 0000C6
5 GU
DE039 (GE) SG19812 *---(EL24611 EQ
)
03014900000
32327200000
A A000_RETR_DE039_ALL
0.000033 0001D0
6 GNP
DE039 (GP) SG19813 *---
No Parentage Established
•
Because NOT set
Use IMSTRACE whilst testing and check call sequence is becoming the
standard within the bank. If this can’t help then use DISPLAYs or Debuggers.
Westpac usage – Performance
C LKI99
11.3010066 0009F6
4 GN
DE039 (
) SG31330 *---(EL03317 = A785623300)
.
.
A A000_RETR_DE039_ALL
0.000128 0001D0
7 GNP
DE039 (
) SG19813 *F--(EL18772 = 177354)
A A000_RETR_DE039_ALL
0.000200 0001D0
8 GNP
DE039 (
) SG19813 *F--(EL18772 = 177356)
A A000_RETR_DE039_ALL
0.000260 0001D0
9 GNP
DE039 (
) SG19813 *F--(EL18772 = 177358)
•
Response time (in secs) for each call can be used to highlight areas that require
tuning or (as above) inappropriate calls for a database type – GN on a root
segment with a qualified key within a HDAM database will perform a sequential
scan.
•
In addition to showing the flow of DL/I calls and redundant DL/I calls, both of
which can be used to optimise the database navigation, the misuse of command
codes was evident in many programs within several applications. In the above
example the program is retrieving dependent segments in ascending key
sequence and hence does not need to use the F command code (start searching
from the first.
Westpac usage – QA
A <==<LKD70>
A LKJ34
0.000010 0019C6
1 INQY DB815
(
) FIND
DB815A
C LKJ34
0.001046 005510
2 GU
DE019
(
) SG22905 *---(GR30003EQ45)
C LKJ34
0.000029 0058EC
3 GNP
DE019
(
) SG22907 *---
A LKJ38
0.000012 000C24
4 INQY DB815
(
) FIND
C LKJ38
0.001043 001518
5 GU
(
) SG22923 *---(EL30033 EQ *)
A <==<LKJ34>==<LKD70>
DE020
DB815A
05
7C
C <==<LKD70>
C LKJ34
0.000062 0085B8
6 GU
DE020
(
) SG22923 *---(EL30033 EQ *)
05
7C
0.000038 002FE2
7 GU
DE020
(
) SG22923 *P--(EL30033 EQ..
C <==<LKJ34>==<LKD70>
C LKIP019
.
.
•
Review/Walkthru of the IMSTRACE report is conducted within some
Application teams to ensure, as much as possible, efficient, standard and quality
IMS programs are lodged into production.
Some Stories from Westpac
•
Programmer spent 1 week debugging PL/I IMS program with no success.
After enabling the IMSTRACE it was found that a lower-level module was
not checking the status code but was actually getting AJ status (invalid
SSA). Took 5 mins to find the problem with IMSTRACE.
•
Program performing badly prior to production lodgement. IMSTRACE
enabled and within minutes the offending call (reported with a response
time of 11 secs) was a GN on a root segment specifying a key value on a
HDAM database. HDAM databases are scanned sequentially when used in
this manner.
•
Programmer spent 3 days debugging COBOL IMS program by using
DISPLAY statements. IMSTRACE enabled and within 1 minute it was
found that the wrong SSA was being displayed (as it was the one suspected).
The problem was the wrong key in another unrelated SSA.
Some Stories from Westpac
•
New version of a program (just lodged) was causing problems. IMSTRACE
showed status code AK (invalid field name) on a call that “appeared” to be
working. Inspecting the program it was found that the wrong PCB was
being used in a call and hence the status code checking for that call appeared
to be OK . As this is a complex program the staff were quoted as saying “we
solved the problem in minutes. Without the IMSTRACE it would have
taken days as we never would have suspected that part of the program and
we would have assumed the problem was environmental”.
•
“We estimate that the IMSTRACE saved us 25% in the total project cost by
significantly reducing our analysis, testing and debug time whilst also
improving the overall system quality & performance. This is a big saving.
It is so easy to use, is enabled in a couple of seconds without the need to
recompile the program, and we can (and have) used it in production if
required” – Glenn Bowden, Project Manager Decapping Project, Westpac
banking Corporation.
Why AMPDEV IMSTrace?
• Works off EXECUTABLE LOAD module.
–You never re-compile (cause that is risky, and a hassle).
–No source changes required. Can be enabled in a few seconds.
• Supports PL/I, COBOL and ASM running under Language
Environment (LE)
• Supports IMS/DB, IMS/DC (or IMS/TM), CICS with IMS
DBCTL
• NO JCL changes required to execute the trace
• Run-time options can be set dynamically