Transcript SQL TRace - Go

tkprof: Who? What? How?
When? Where? Why?
-orDavid Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
1
SQL Trace: All of the Questions
and None of the Answers
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
2
Resources
• If you can’t hear me say so now.
• Please feel free to ask questions as we go
along.
• The presentation will be available from
• www.ukoug.org
• www.go-faster.co.uk
www.go-faster.co.uk
3
Sales Pitch
• DBA
– Independent consultant
– Performance tuning
• PeopleSoft
– UKOUG Unix SIG
www.go-faster.co.uk
4
Chief Objective
• How to think about performance issues.
www.go-faster.co.uk
5
Two Chief Objectives
• How to think about performance issues.
• How to use TKPROF to help solve those
problems.
www.go-faster.co.uk
6
Among a number of Chief
Objectives
• How to think about performance issues.
• How to use TKPROF to help solve those
problems.
• How easy it is to present at UKOUG SIG
meetings.
www.go-faster.co.uk
7
UKOUG Unix SIG
• Next Meeting
– 10th June 2004
– Meriden, Solihull
– www.ukoug.org
• BQUFTH
• What are you going to present?
– Perhaps you didn’t expect the Spanish Inquisition!
www.go-faster.co.uk
8
Surprise, Fear and Ruthless
Efficiency
www.go-faster.co.uk
9
How to think about performance
issues?
• All the tools are free!
• And this is the most
important tool of all:
www.go-faster.co.uk
10
Performance is exactly
what the user
perceives it to be. No
more, no less.
Performance is ‘poor’
when the user’s
perception does not
match their
expectation.
www.go-faster.co.uk
11
YAPP
• R=S+W
• YAPP
• 1999
– Where
• R = response time
• S = service time
• W = wait time
– Anjo Kolk
– Shari Yamaguschi
– Jim Viscusi
• www.oraperf.com
www.go-faster.co.uk
12
Detection is, or ought to be, an exact science.
It should be treated in the same cold and
unemotional manner.
The Sign of Four, Arthur Conan-Doyle
www.go-faster.co.uk
13
‘A Practitioners Guide to
Optimizing Response Time’
• Optimizing Oracle
Performance
• Cary Millsap
• with Jeff Holt
– O’Reilly
• www.hotsos.com
www.go-faster.co.uk
14
Another book – also
recommended by Cary Millsap
• The Goal: A Process
of Ongoing
Improvement
• Eliyahu Goldratt, Jeff
Cox
www.go-faster.co.uk
15
Identify your bottlenecks
Performance Tuning is a search for lost time.
Time lost at a bottleneck is not just time lost
at a bottleneck, it affects the whole system.
If it isn’t a problem, or it isn’t going to be a
problem, then don’t tune it.
www.go-faster.co.uk
16
Metrics
• Users
– Often very useful, but not always 100% reliable
• Webserver
• Application Server
• Batch scheduling software
www.go-faster.co.uk
17
Sources of metrics
Proxy Server
Access Log
Webserver
Access Log
http /
https
Java
Servlet
(presentation
logic)
Tuxedo
tmadmin
script
Tuxedo
Message
Oracle
SQL*Trace
Tuxedo
Service
Trace
Tuxedo
Application
Server
(application
logic)
www.go-faster.co.uk
DBMS
SQL
(application data
& meta-data
18
Webserver access log
#Version: 1.0
#Fields:
date time time-taken bytes c-ip c-dns cs-method sc-status cs-uri-stem cs-uri-query
2003-12-0109:44:38 0.192
726
10.1.37.148
10.1.37.148
GET
200
/psp/f84dev/EMPLOYEE/ERP/c/REQUISITION_ITEMS.REQUISITIONS.GBL
Folder=MYFAVORITES
2003-12-0109:44:38 0.312
4506
10.1.37.148
10.1.37.148
GET
200
/psc/f84dev/EMPLOYEE/ERP/s/WEBLIB_PT_NAV.ISCRIPT1.FieldFormula.IScript_
PT_NAV_INFRAME
c=1h%2bwtoAlFUliqGxwwyIRXz9HzFApegKe&Folder=MYFAVORITES&PortalActua
lURL=http%3a%2f%2fxxx.com%2fpsc%2ff84dev%2fEMPLOYEE%2fERP%2fc%2fREQUISI
TION_ITEMS.REQUISITIONS.GBL%3fFolder%3dMYFAVORITES&PortalContentURL=http
%3a%2f%2fxxx.com%2fpsc%2ff84dev%2fEMPLOYEE%2fERP%2fc%2fREQUISITION_ITE
MS.REQUISITIONS.GBL&PortalContentProvider=ERP&PortalRegistryName=EMPLOYEE&
PortalServletURI=http%3a%2f%2fxxx.com%2fpsp%2ff84dev%2f&PortalURI=http%3a%2f%
2fxxx.com%2fpsc%2ff84dev%2f&PortalHostNode=ERP&PortalIsPagelet=true&NoCrumbs=
yes
www.go-faster.co.uk
19
Longest http conversations
www.go-faster.co.uk
20
So what should I SQL trace?
• If I know which business transactions are
my bottleneck…
• …and if I understand the structure of the
application in question…
• then I can determine which session I should
trace.
www.go-faster.co.uk
21
What is SQL trace?
• Session or database level
• Session’s shadow process writes to a text
file in user_dump_dest.
• Trace file contains
–
–
–
–
User and recursive SQL statements
Execution plan, phyiscal & logical reads
Timing information
Wait and bind information (optional)
www.go-faster.co.uk
22
What is SQL trace?
• First appeared in Oracle 6.
• More instrumentation added at each release.
• Not friendly format, can be read by humans.
– And sometimes that is necessary
• Usually process it with tkprof
www.go-faster.co.uk
23
Initialisation parameters
•
•
•
•
•
timed_statistics = TRUE
user_dump_dest = '<directory name>'
max_dump_file_size = <size>
_trace_files_public = TRUE
trace_file_identifier = '<string>'
www.go-faster.co.uk
24
timed_statistics = TRUE
• You must set this initialisation variable to
true
– otherwise you won’t get any timing information
anywhere in the database
– including the SQL trace files
– Low overhead
– Always set it true
www.go-faster.co.uk
25
max_dump_file_size
• Be careful that your trace files are not
truncated.
– look at tail for message
• DUMP FILE SIZE IS LIMITED
– Your file may be truncated prior to the point of
interest.
– Parameter expressed in O/S blocks, Kb, or Mb
– Dynamic parameter from Oracle 9.x
www.go-faster.co.uk
26
_trace_files_public = TRUE
• This parameter controls the OS permission
of the trace file.
– Setting it true allows the trace file to be read
outside the DBA group
– Not dynamically alterable.
– Consider security issue.
www.go-faster.co.uk
27
tracefile_identifier = <string>
• Set at init.ora or setting level
– Available from Oracle 8.1.7
– Trace file identifier string appended to name of
trace file
– Can alter after starting trace, and so get two
trace files.
– Do not put space ( ) or hyphen (-) in the
identifier. You get an invalid file error.
www.go-faster.co.uk
28
tracefile_identifier = <string>
ALTER SESSION SET
TRACE_FILE_IDENTIFIER =
‘nVision_Report_NVSRUN_159’;
/u01/app/oracle/admin/F84SP1/udu
mp/f84sp1_ora_41776_nVision_Rep
ort_NVSRUN_159.trc
www.go-faster.co.uk
29
How to enable SQL trace
• From UKOUG2002
– Advanced Oracle Diagnostics
• Julian Dyke
– www.juliandyke.com
– Chair of UKOUG RAC SIG
– 10 methods of enabling trace information in
Oracle
www.go-faster.co.uk
30
How to enable SQL trace
ALTER SESSION SET EVENTS '10046 trace
name context forever, level <n>'
Level
Description
0
Disabled
1
Same as ALTER SESSION SET
SQL_TRACE=TRUE
4
Include bind variable information
8
Include wait statistics
12
Include bind variable and wait statistics
www.go-faster.co.uk
31
How to enable SQL trace
• At instance level
# Enable SQL trace for instance
sql_trace = TRUE
– or
# Enable SQL*trace with binds for instance
event = '10046 trace name context forever, level 4';
www.go-faster.co.uk
32
How to disable SQL trace
• SQL Trace parameter cannot be altered directly
--Enable SQL trace for instance
ALTER SYSTEM SET EVENTS
'10046 trace name context forever, level 1;
– or
--Disable trace for instance
ALTER SYSTEM SET EVENTS
'10046 trace name context off';
www.go-faster.co.uk
33
How to enable SQL trace
• Either
--Enable SQL trace for instance
ALTER SYSTEM SET SQL_TRACE=TRUE;
• or
--Disable trace for instance
ALTER SYSTEM SET SQL_TRACE=FALSE;
www.go-faster.co.uk
34
How to enable SQL trace
• Either
--Enable SQL trace for session
ALTER SESSION SET SQL_TRACE=TRUE;
• or
--Disable trace for session
ALTER SESSION SET SQL_TRACE=FALSE;
www.go-faster.co.uk
35
How to enable SQL trace
• In current session with supplied PL/SQL
procedures
--Enable SQL trace for session
DBMS_SESSION.SET_SQL_TRACE
(
FLAG BOOLEAN
-- TRUE to enable;
-- FALSE to disable
);
www.go-faster.co.uk
36
How to enable SQL trace
• In current session
--Enable SQL trace for session
DBMS_SUPPORT.START_TRACE
(
WAITS BOOLEAN, -- Include waits (default FALSE)
BINDS BOOLEAN -- Include binds (default FALSE)
);
--Disable SQL Trace for session
DBMS_SUPPORT.STOP_TRACE;
www.go-faster.co.uk
37
How to enable SQL trace
• In another session
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION
(
SI NUMBER,
-- SID
SE NUMBER,
-- Serial Number
SQL_TRACE BOOLEAN -- TRUE to enable;
-- FALSE to disable
);
• SID and SERIAL# from V$SESSION.
www.go-faster.co.uk
38
How to enable SQL trace
• In another session
DBMS_SUPPORT.START_TRACE_IN_SESSION
(
SI NUMBER,
-- SID
SE NUMBER,
-- Serial Number (can be 0)
WAITS BOOLEAN, -- Include waits (default FALSE)
BINDS BOOLEAN -- Include binds (default FALSE)
);
www.go-faster.co.uk
39
How to disable SQL trace
• In another session
DBMS_SUPPORT.STOP_TRACE_IN_SESSION
(
SI NUMBER,
-- SID
SE NUMBER,
-- Serial Number (can be 0)
);
www.go-faster.co.uk
40
How to enable SQL trace
• Set event in another session
DBMS_SYSTEM.SET_EV
(
SI NUMBER,
-SE NUMBER,
-EV NUMBER,
-LE NUMBER,
-NM VARCHAR2
-);
SID
Serial Number (can be 0)
Event Number e.g. 10046
Level e.g. 4
Action Name – can be '‘
• Disable with level 0
www.go-faster.co.uk
41
Using logon triggers to enable
SQL trace
• Login trigger to trace from the very
beginning.
CREATE OR REPLACE TRIGGER
sys.trace_logon_sysadm
AFTER LOGON ON sysadm.schema
BEGIN
sys.dbms_session.set_sql_trace(true);
END;
/
www.go-faster.co.uk
42
Using triggers to enable SQL
trace (i)
• Trigger fired by starting process.
CREATE OR REPLACE TRIGGER sysadm.set_trace
AFTER UPDATE OF runstatus
ON sysadm.psprcsrqst FOR EACH ROW
WHEN (new.runstatus = 7 and old.runstatus != 7
AND new.prcstype IN('Application Engine','COBOL
SQL','Crystal','nVision-Report','SQR Process','SQR
Report','SQR Report For WF Delivery')
--AND new.prcsname = ‘GPPDPRUN’
AND new.begindttm <=
TO_DATE('200312031800','YYYYMMDDHH24MI'))
www.go-faster.co.uk
43
Using triggers to enable SQL
trace (ii)
BEGIN
EXECUTE IMMEDIATE 'ALTER SESSION SET TIMED_STATISTICS =
TRUE';
EXECUTE IMMEDIATE 'ALTER SESSION SET MAX_DUMP_FILE_SIZE =
UNLIMITED';
EXECUTE IMMEDIATE 'ALTER SESSION SET TRACEFILE_IDENTIFIER =
'''||
translate(:new.prcstype,' -','__')||'_'||
translate(:new.prcsname,' -','__')||'_'||
:new.prcsinstance||'''';
EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 trace
name context forever, level 8''';
END;
/
www.go-faster.co.uk
44
Other Events
• Other write additional information to trace
file
–
–
–
–
–
–
10128 – Partition Elimination
10053 – CBO Analysis
10104 – Hash Activity
10032 – Sort Statistics
10033 – Sort I/O
10391 – Parallel Slave
www.go-faster.co.uk
45
What is in the SQL trace file
• See Metalink Note 39817.1 for details of
trace file structure
www.go-faster.co.uk
46
SQL trace file sections
• Trace Sections
– DBMS_APPLICATION_INFO settings
– Cursors
– Operations
• Parse, exec, fetch, (sort) unmap
– Errors
– Stat
• Execution Plans
– Xctend
• End of transaction
www.go-faster.co.uk
47
SQL trace file sections
• With event 10046
– Binds
– Waits
• Timings
– centisecond timings (Oracle 7 & 8)
– microsecond from Oracle 9
www.go-faster.co.uk
48
SQL trace file contents
/u01/app/oracle/admin/F84SP1/udump/f84sp1_ora_41776_nVision_Report
_NVSRUN_159.trc
…
Oracle9i Enterprise Edition Release 9.2.0.1.0 - 64bit Production
JServer Release 9.2.0.1.0 - Production
ORACLE_HOME = /u01/app/oracle/product/9.2.0
System name:
AIX
Node name:
xxxxxxxxx
Release: 3
Version: 4
Machine: 0000C6BF4C00
Instance name: F84SP1
Redo thread mounted by this instance: 1
Oracle process number: 28
Unix process pid: 41776, image: oracle@xxxxxxxxx (TNS V1-V3)
www.go-faster.co.uk
49
SQL trace file contents
PARSING IN CURSOR #3 len=58 dep=0 uid=24 oct=3 lid=24
tim=1045288408856870 hv=2952492898 ad='3b36970'
SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS'
END OF STMT
PARSE #3:c=0,e=1836,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,
tim=1045288408856862
EXEC #3:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,
tim=1045288408857230
WAIT #3: nam='SQL*Net message to client' ela= 3 p1=1413697536 p2=1
p3=0
FETCH #3:c=0,e=75,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=4,
tim=1045288408857420
WAIT #3: nam='SQL*Net message from client' ela= 47544 p1=1413697536
p2=1 p3=0
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=31453 op='TABLE ACCESS BY INDEX
ROWID PSVERSION '
STAT #3 id=2 cnt=1 pid=1 pos=1 obj=31454 op='INDEX UNIQUE SCAN
PS_PSVERSION '
www.go-faster.co.uk
50
tkprof
• Oracle supplied utility
– Processes SQL trace files
– Provides a easy to read report
• Timings
• Sorted by CPU or Elapsed Timings
• Wait analysis from Oracle 9
– Even on Oracle 8 trace!
• Execution plans
• Aggregate identical statements
www.go-faster.co.uk
51
tkprof sample
SELECT VERSION
FROM
PSVERSION WHERE OBJECTTYPENAME = 'SYS'
call
count
------- -----Parse
1
Execute
1
Fetch
1
------- -----total
3
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
0.00
0.00
0
0
0
0.00
0.00
0
2
0
-------- ---------- ---------- ---------- ---------0.00
0.00
0
2
0
rows
---------0
0
1
---------1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 24
Rows
------1
1
Row Source Operation
--------------------------------------------------TABLE ACCESS BY INDEX ROWID PSVERSION
INDEX UNIQUE SCAN PS_PSVERSION (object id 31454)
www.go-faster.co.uk
52
Row source statistics
• From Oracle 9.2.0.2
– Added to SQL Trace stat line
– Appears in tkprof output
– Performance overhead
• See BQFTH in Oracle Scene 16
• Oracle Bug 3009359
www.go-faster.co.uk
53
Row source statistics
SELECT A.START_DATE, A.STOP_DATE
FROM
PS_X_PYE_OVRD_ET A WHERE A.EMPLID= :1 AND A.EMPL_RCD= :2 AND A.PIN_NUM=
:3 AND A.START_DATE<= :4 AND A.STOP_DATE>= :5 AND A.START_DATE<= :6
ORDER BY A.START_DATE DESC
call
------Parse
Execute
Fetch
------total
count
-----1
116759
116759
-----233519
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.02
0.17
0
0
0
20.76
40.24
0
0
0
25.60
88.40
1910
440408
0
-------- ---------- ---------- ---------- ---------46.38
128.81
1910
440408
0
www.go-faster.co.uk
rows
---------0
0
89622
---------89622
54
Row source statistics
Rows
------89622
Row Source Operation
--------------------------------------------------SORT ORDER BY
(cr=440408 r=1910 w=0 time=72942929 us)
89622
PARTITION RANGE SINGLE PARTITION: KEY KEY
(cr=440408 r=1910 w=0 time=58756548 us)
89622
TABLE ACCESS BY LOCAL INDEX ROWID OBJ#(165144)
PARTITION: KEY KEY
(cr=440408 r=1910 w=0 time=57904868 us)
89622
INDEX RANGE SCAN DESCENDING OBJ#(166035)
PARTITION: KEY KEY
(cr=350786 r=451 w=0 time=20700497 us)
(object id 166035)
www.go-faster.co.uk
55
How to tune with tkprof
• Identify your bottlenecks
– Decide what to trace
– Enable SQL trace
– Tkprof
•
•
•
•
Sort=(fchela,exeela,prsela)
Waits=yes
Print=10
Explain=<connect string>
www.go-faster.co.uk
56
Example 1: SQL Problem
• You have traced your process…
• you run tkprof…
• And at the top of the report you have a big
block of SQL.
• What do you do next?
www.go-faster.co.uk
57
SQL statement
INSERT INTO PS_PP_CUST_TMP2 ( PROCESS_INSTANCE, DEPOSIT_BU, DEPOSIT_ID,
PAYMENT_SEQ_NUM, CUST_ID, PAYMENT_AMT, PAYMENT_DT, PP_METHOD, SETID,
SUBCUST_QUAL1, SUBCUST_QUAL2, PP_HOLD, PP_MET_SW, PAYMENT_CURRENCY )
SELECT DISTINCT P.PROCESS_INSTANCE, P.DEPOSIT_BU, P.DEPOSIT_ID,
P.PAYMENT_SEQ_NUM, C.CUST_ID, P.PAYMENT_AMT, P.PAYMENT_DT, O.PP_METHOD,
O.SETID, C.SUBCUST_QUAL1, C.SUBCUST_QUAL2, O.PP_HOLD, 'N',
P.PAYMENT_CURRENCY
FROM PS_CUST_OPTION O, PS_ITEM I, PS_CUSTOMER C,
PS_SET_CNTRL_REC S, PS_PAYMENT_ID_ITEM X, PS_PP_PAYMENT_TMP P
WHERE
P.PROCESS_INSTANCE = 212
AND S.RECNAME = 'CUSTOMER'
AND S.SETID =
C.SETID
AND S.SETCNTRLVALUE = I.BUSINESS_UNIT
AND I.CUST_ID =
C.CUST_ID
AND I.ITEM_STATUS = 'O'
AND O.SETID = C.REMIT_FROM_SETID
AND O.CUST_ID = C.REMIT_FROM_CUST_ID
AND O.EFFDT = ( SELECT
MAX(Z.EFFDT) FROM PS_CUST_OPTION Z
WHERE Z.SETID =
O.SETID
AND Z.CUST_ID = O.CUST_ID
AND Z.EFF_STATUS = 'A'
AND Z.EFFDT <=
P.PAYMENT_DT )
AND O.PP_METHOD <> ' '
AND P.DEPOSIT_BU =
X.DEPOSIT_BU
AND P.DEPOSIT_ID = X.DEPOSIT_ID
AND P.PAYMENT_SEQ_NUM =
X.PAYMENT_SEQ_NUM
AND X.REF_QUALIFIER_CODE = 'I'
AND X.REF_VALUE =
I.ITEM
www.go-faster.co.uk
58
Statistics
…
count
=
cpu
=
elapsed =
disk
=
query
=
current =
update)
rows
=
number of times OCI procedure was executed
cpu time in seconds executing
elapsed time in seconds executing
number of physical reads of buffers from disk
number of buffers gotten for consistent read
number of buffers gotten in current mode (usually for
number of rows processed by the fetch or execute call
…
call
count
------- -----Parse
1
Execute
1
Fetch
0
------- -----total
2
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.31
0.33
4
0
4
156.61
160.23
164769
3981545
0
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------156.92
160.56
164773
3981545
4
www.go-faster.co.uk
rows
---------0
0
0
---------0
59
Execution plan (from stat lines)
Rows
------0
0
0
0
8
1000040
360
10
10
11
20
360
370
1000040
1000400
1000048
8
16
0
0
0
Execution Plan
--------------------------------------------------INSERT STATEMENT
GOAL: CHOOSE
SORT (UNIQUE)
FILTER
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
TABLE ACCESS BY INDEX ROWID PS_PP_PAYMENT_TMP
INDEX (RANGE SCAN) (object id 9329)
INDEX (RANGE SCAN) OF (object id 8105)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_SET_CNTRL_REC'
INDEX (RANGE SCAN) OF (object id 12020)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUSTOMER'
INDEX (RANGE SCAN) OF (object id 4751)
INDEX (RANGE SCAN) OF 'PS#ITEM' (NON-UNIQUE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF (object id 4854)
SORT (AGGREGATE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF (object id 4854)
www.go-faster.co.uk
60
Execution plan (if you connect
tkprof to the database)
Rows
------0
0
0
0
8
1000040
360
10
10
11
20
360
370
1000040
1000400
1000048
8
16
0
0
0
Execution Plan
--------------------------------------------------INSERT STATEMENT
GOAL: CHOOSE
SORT (UNIQUE)
FILTER
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
TABLE ACCESS (BY INDEX ROWID) OF
'PS_PP_PAYMENT_TMP'
INDEX (RANGE SCAN) OF 'PSAPP_PAYMENT_TMP'
(NON-UNIQUE)
INDEX (RANGE SCAN) OF 'PSAPAYMENT_ID_ITEM'
(NON-UNIQUE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_SET_CNTRL_REC'
INDEX (RANGE SCAN) OF 'PSBSET_CNTRL_REC'
(NON-UNIQUE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUSTOMER'
INDEX (RANGE SCAN) OF 'PS#CUSTOMER' (NON-UNIQUE)
INDEX (RANGE SCAN) OF 'PS#ITEM' (NON-UNIQUE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE)
SORT (AGGREGATE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE)
www.go-faster.co.uk
61
1. Make the statement readable
SELECT DISTINCT P.PROCESS_INSTANCE, P.DEPOSIT_BU, P.DEPOSIT_ID,
P.PAYMENT_SEQ_NUM, C.CUST_ID, P.PAYMENT_AMT, P.PAYMENT_DT, O.PP_METHOD,
O.SETID, C.SUBCUST_QUAL1, C.SUBCUST_QUAL2, O.PP_HOLD, 'N',
P.PAYMENT_CURRENCY
FROM
PS_CUST_OPTION O, PS_ITEM I, PS_CUSTOMER C,
PS_SET_CNTRL_REC S, PS_PAYMENT_ID_ITEM X, PS_PP_PAYMENT_TMP P
WHERE P.PROCESS_INSTANCE = 212
AND
S.RECNAME = 'CUSTOMER'
AND
S.SETID = C.SETID
AND
S.SETCNTRLVALUE = I.BUSINESS_UNIT
AND
I.CUST_ID = C.CUST_ID
AND
I.ITEM_STATUS = 'O'
AND
O.SETID = C.REMIT_FROM_SETID
AND
O.CUST_ID = C.REMIT_FROM_CUST_ID
AND
O.EFFDT = ( SELECT
MAX(Z.EFFDT)
FROM
PS_CUST_OPTION Z
WHERE
Z.SETID = O.SETID
AND
Z.CUST_ID = O.CUST_ID
AND
Z.EFF_STATUS = 'A'
AND
Z.EFFDT <= P.PAYMENT_DT)
AND O.PP_METHOD <> ' '
AND P.DEPOSIT_BU = X.DEPOSIT_BU
AND P.DEPOSIT_ID = X.DEPOSIT_ID
AND P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM
AND X.REF_QUALIFIER_CODE = 'I'
AND X.REF_VALUE = I.ITEM
www.go-faster.co.uk
62
2. Start to draw the query
PS_CUST_OPTION
O
PS_CUSTOMER
C
PS_SET_CNTRL_REC
S
PS_ITEM
I
PS_PAYMENT_ID_ITEM
X
PS_PP_PAYMENT_TMP
P
www.go-faster.co.uk
63
3. Put the joins in
EFFDT
PP_METHOD <> ' '
PS_CUST_OPTION
O
PS_CUSTOMER
C
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
CUST_ID
SETID
PS_SET_CNTRL_REC
S
S.SET
C
NTRL
VALU
E = I.B
USINE
SS_U
NIT
PS_ITEM
I
RECNAME = 'CUSTOMER'
LUE
F_VA
X.RE
PS_PAYMENT_ID_ITEM
X
REF_QUALIFIER_CODE = 'I'
www.go-faster.co.uk
ITEM_STATUS = 'O'
EM
= I.IT
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
PS_PP_PAYMENT_TMP
P
PROCESS_INSTANCE
= 212
64
4. Get the order from the plan
0
0
8
1000040
360
10
10
11
20
360
370
1000040
1000400
1000048
8
16
0
0
FILTER
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
NESTED LOOPS
(1)TABLE ACCESS (BY INDEX ROWID) OF
'PS_PP_PAYMENT_TMP'
INDEX (RANGE SCAN) OF 'PSAPP_PAYMENT_TMP'
(NON-UNIQUE)
(2)INDEX (RANGE SCAN) OF 'PSAPAYMENT_ID_ITEM'
(NON-UNIQUE)
(3)TABLE ACCESS (BY INDEX ROWID) OF 'PS_SET_CNTRL_REC'
INDEX (RANGE SCAN) OF 'PSBSET_CNTRL_REC'
(NON-UNIQUE)
(4)TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUSTOMER'
INDEX (RANGE SCAN) OF 'PS#CUSTOMER' (NON-UNIQUE)
(5)INDEX (RANGE SCAN) OF 'PS#ITEM' (NON-UNIQUE)
(6)TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE)
SORT (AGGREGATE)
TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION'
INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE)
www.go-faster.co.uk
65
5. Put the order in the diagram
EFFDT
PP_METHOD <> ' '
PS_CUST_OPTION
O (6)
PS_CUSTOMER
C (4)
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
CUST_ID
SETID
PS_SET_CNTRL_REC
S (3)
S.SET
C
NTRL
VALU
E=
I.BUS
INESS
_UNIT
PS_ITEM
I (5)
RECNAME = 'CUSTOMER'
LUE
F_VA
X.RE
PS_PAYMENT_ID_ITEM
X (2)
= I.IT
EM
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
REF_QUALIFIER_CODE = 'I'
www.go-faster.co.uk
ITEM_STATUS = 'O'
PS_PP_PAYMENT_TMP
P (1)
PROCESS_INSTANCE
= 212
66
6. This time, the answer is an
index
CREATE INDEX PSBITEM ON PS_ITEM
(ITEM,
CUST_ID,
BUSINESS_UNIT,
ITEM_STATUS)
TABLESPACE PSINDEX
STORAGE (INITIAL 10K NEXT 98K
MAXEXTENTS 110 PCTINCREASE 0)
/
www.go-faster.co.uk
67
New execution order
EFFDT
PP_METHOD <> ' '
PS_CUST_OPTION
O (6)
PS_CUSTOMER
C (5)
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
CUST_ID
SETID
PS_SET_CNTRL_REC
S (4)
S.SET
C
NTRL
VALU
E = I.B
USINE
SS_U
NIT
PS_ITEM
I (3)
RECNAME = 'CUSTOMER'
LUE
F_VA
X.RE
PS_PAYMENT_ID_ITEM
X (2)
EM
= I.IT
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
REF_QUALIFIER_CODE = 'I'
www.go-faster.co.uk
ITEM_STATUS = 'O'
PS_PP_PAYMENT_TMP
P (1)
PROCESS_INSTANCE
= 212
68
Statistics
Before
call
count
------- -----Parse
1
Execute
1
Fetch
0
------- -----total
2
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.31
0.33
4
0
4
156.61
160.23
164769
3981545
0
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------156.92
160.56
164773
3981545
4
rows
---------0
0
0
---------0
After
call
count
------- -----Parse
1
Execute
1
Fetch
0
------- -----total
2
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.35
2.56
3
0
3
0.03
0.05
38
289
3
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------0.38
2.61
41
289
6
www.go-faster.co.uk
rows
---------0
0
0
---------0
69
Example 2: Wait Events
• How do you know it’s not the database?
• Event 10046,8 – enable wait information.
www.go-faster.co.uk
70
CPU –v- elapsed time
INSERT /*GPPRDMGR_I_ACUM*/ INTO PS_GP_RSLT_ACUM (CAL_RUN_ID ,EMPLID ,EMPL_RCD
,GP_PAYGROUP ,CAL_ID ,RSLT_SEG_NUM ,PIN_NUM ,EMPL_RCD_ACUM ,ACM_FROM_DT ,
ACM_THRU_DT ,USER_KEY1 ,USER_KEY2 ,USER_KEY3 ,USER_KEY4 ,SLICE_BGN_DT ,
SLICE_END_DT ,COUNTRY ,ACM_TYPE ,ACM_PRD_OPTN ,CALC_RSLT_VAL ,CALC_VAL ,
USER_ADJ_VAL ,PIN_PARENT_NUM ,CORR_RTO_IND )
VALUES
(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15,:16,:17,:18,:19,:20,:21,
:22,:23,:24)
call
count
------- -----Parse
1
Execute 22510
Fetch
0
------- -----total
22511
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
73.30
1269.24
31542
45040
503607
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------73.30
1269.24
31542
45040
503607
www.go-faster.co.uk
rows
---------0
558966
0
---------558966
71
Wait events report discrepancy
Elapsed times include waiting on following events:
Event waited on
Times
Max. Wait
----------------------------Waited ---------SQL*Net more data from client
27495
0.56
db file sequential read
31542
0.97
SQL*Net message from client
22510
0.44
SQL*Net message to client
22510
0.01
latch free
5
0.02
free buffer waits
19
1.02
buffer busy waits
1
0.00
log file switch completion
1
0.06
www.go-faster.co.uk
Total Waited
-----------1036.26
148.99
80.41
0.08
0.08
4.74
0.00
0.06
72
After resolving network problem
call
count
------- -----Parse
1
Execute 22264
Fetch
0
------- -----total
22265
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
103.07
113.04
2521
86624
553966
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------103.07
113.04
2521
86624
553966
Event waited on
----------------------------SQL*Net more data from client
SQL*Net message from client
Times
Waited
29138
22264
Max. Wait
---------0.47
0.47
www.go-faster.co.uk
rows
---------0
662676
0
---------662676
Total Waited
-----------6.69
88.84
73
Example 3: Waits events
UPDATE /*GPPDPDM4_U_TRIGGER*/ PS_GP_SEG_TRGR SET CAL_RUN_ID =:1
WHERE
TRGR_EFFDT>=:2 AND TRGR_EFFDT<=:3 AND EMPLID=:4 AND COUNTRY=:5 AND
SEG_TRGR_STATUS='A' AND CAL_RUN_ID=' ' AND (EMPL_RCD=:6 OR SEG_TRGR_LVL='E')
AND TRGR_EVENT_ID IN (SELECT SEC.TRGR_EVENT_ID FROM PS_GP_SEG_EVT SEC
WHERE SEC.SEG_TYPE='P' AND SEC.COUNTRY=:7 )
call
count
------- -----Parse
5858
Execute 27973
Fetch
0
------- -----total
33831
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.57
0.51
0
0
0
7.60
1989.00
1630
95825
662
0.00
0.00
0
0
0
-------- ---------- ---------- ---------- ---------8.17
1989.52
1630
95825
662
www.go-faster.co.uk
rows
---------0
645
0
---------645
74
Wait Events
Elapsed times include waiting on following events:
Event waited on
Times
Max. Wait Total Waited
--------------------------Waited ---------- -----------SQL*Net message to client
27973
0.00
0.05
SQL*Net message from client
27973
1.34
99.10
db file sequential read
1630
0.27
8.67
enqueue
658
3.34
1973.10
latch free
2
0.00
0.00
www.go-faster.co.uk
75
Example 4: Idle wait?
• SQL*Net message from client
– Often call an idle wait
– It means that the database is idle
– What is a ‘batch’ process?
www.go-faster.co.uk
76
What is a ‘batch’ process?
• It is a process that runs for a period of time
without waiting for user input.
• So if the database is idle then the client
process must be busy.
• SQL*Net message from client
=Application busy time
www.go-faster.co.uk
77
Summary at bottom of report
• Active process making lots of calls to the
database
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call
------Parse
Execute
Fetch
------total
count
cpu
elapsed
disk
query
current
------ -------- ---------- ---------- ---------- ---------12197
3.85
4.50
621
25979
0
870343
537.36
750.89
70625
18372702
2047141
710951
405.99
917.94
229999
10341004
73
------ -------- ---------- ---------- ---------- ---------1593491
947.20
1673.34
301245
28739685
2047214
www.go-faster.co.uk
rows
---------0
2657717
3030039
---------5687756
78
Is it the database?
Elapsed times include waiting on following events:
Event waited on
Times
Max. Wait
----------------------------Waited ---------SQL*Net message to client
881285
0.01
SQL*Net message from client
881285
1.22
log file sync
185
1.01
SQL*Net more data from client
62845
0.40
SQL*Net more data to client
21008
0.00
db file sequential read
201760
2.39
direct path write
2632
0.67
direct path read
4034
0.71
www.go-faster.co.uk
Total Waited
-----------1.68
2491.24
28.18
5.27
1.54
451.60
49.76
28.97
79
Is it the database?
• Perhaps this time we should look at the
application
Batch process elapsed time
SQL*Net message from client
Database Time
Unaccounted for (CPU contention?)
www.go-faster.co.uk
4790
2491
1673
626
80
Example 4: tkprof can mislead
• Different plans
– One from stat lines
• How the statement was actually executed
– One from ‘explain plan for’ command
• How the analyser might execute the statement in the
future on the basis of the current statistics
• Some numbers can be nonsense
www.go-faster.co.uk
81
A simple SQL statement
SELECT DISTINCT A.EMPLID, A.NATIONAL_ID
FROM
PS_PERS_NID A , PS_GP_PYE_STAT_WRK P WHERE P.CAL_RUN_ID =:1 AND P.EMPLID
BETWEEN :2 AND :3 AND P.PRD_TYPE <> 'H' AND P.PYE_CALC_STAT < '50' AND
P.EMPLID=A.EMPLID AND A.PRIMARY_NID= :4 ORDER BY A.EMPLID ASC
call
count
------- -----Parse
1
Execute
5598
Fetch
5598
------- -----total
11197
cpu
elapsed
disk
query
current
-------- ---------- ---------- ---------- ---------0.00
0.00
0
0
0
1.06
1.07
0
0
0
4411.76
4644.73
127 183871489
0
-------- ---------- ---------- ---------- ---------4412.82
4645.80
127 183871489
0
www.go-faster.co.uk
rows
---------0
0
1117812
---------1117812
82
Plan from stat lines
Rows
Row Source Operation
------- --------------------------------------------------1117812 SORT UNIQUE
44603520
NESTED LOOPS
68123268
PARTITION RANGE ITERATOR PARTITION: KEY KEY
68123268
TABLE ACCESS BY LOCAL INDEX ROWID PS_GP_PYE_STAT_WRK
PARTITION: KEY KEY
68123268
INDEX RANGE SCAN PARTITION: KEY KEY (object id 273486)
44603520
TABLE ACCESS BY INDEX ROWID PS_PERS_NID
112721190
INDEX RANGE SCAN (object id 157793)
www.go-faster.co.uk
83
Plan from ‘explain plan for’
Rows
Execution Plan
------- --------------------------------------------------0 SELECT STATEMENT
GOAL: CHOOSE
1117812
SORT (UNIQUE)
44603520
MERGE JOIN
68123268
TABLE ACCESS
GOAL: ANALYZED (BY INDEX ROWID) OF
'PS_PERS_NID'
68123268
INDEX
GOAL: ANALYZED (RANGE SCAN) OF 'PS_PERS_NID'
(UNIQUE)
68123268
SORT (JOIN)
44603520
PARTITION RANGE (ITERATOR) PARTITION:KEYKEY
112721190
TABLE ACCESS
GOAL: ANALYZED (BY LOCAL INDEX ROWID) OF
'PS_GP_PYE_STAT_WRK' PARTITION:KEYKEY
0
INDEX
GOAL: ANALYZED (RANGE SCAN) OF
'PS_GP_PYE_STAT_WRK' (UNIQUE) PARTITION:KEYKEY
www.go-faster.co.uk
84
Conclusion
• How to think about performance issues
• IDENTIFY YOUR BOTTLENECKS
– Interview users, Metrics
– Where are you spending you time?
• SQL Trace
– What to trace, How to enable, What’s in it?
• Tkprof
– What can it tell you? When does it mislead?
www.go-faster.co.uk
85
Questions?
www.go-faster.co.uk
86
Aphorism
• You know my methods, apply them.
– A Study in Scarlet, Arthur Conan-Doyle
www.go-faster.co.uk
87
tkprof: Who? What? How? When? Where? Why?
-orSQL Trace: All of the Questions and None of the
Answers
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
88