Transcript SQL TRace - Go

An introduction to SQL*Trace,
TKPROF and Execution Plans
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
Who Am I?
• Oracle Database Specialist
– Independent consultant
• System Performance
tuning
• Book
– www.psftdba.com
– PeopleSoft ERP
– Oracle RDBMS
• UKOUG Director
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
2
UK Oracle User Group
• Annual Conference
– Birmingham UK
– 1-5 December 2008
• Call for Papers is open
– http://conference.ukoug.org
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
3
Resources
• If you can’t hear me say so now.
• Please feel free to ask questions as we go
along.
• The presentation is available from
• Conference website
• www.go-faster.co.uk
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
4
My Motivation
• Performance problems are instinctively
routed to the DBA
• Trace can locate a database problem
• It can also prove that a problem IS NOT a
database problem.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
5
Your Motivation
• How to ask your DBA the right questions.
• How to trace your program.
• How to instrument your program so that
you can relate your trace to your code.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
6
DBA’s Chief Weapons in the
Performance Fight with Development
• Surprise and Fear
– “Surprise! Surprise! The application runs
slowly”
– “I’m afraid I can’t do anything about it. It’s a
problem with the application code.”
• It doesn’t have to be like this.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
7
Agenda
•
•
•
•
SQL Trace
Execution Plans
Timing Information
Application Instrumentation
• How to use these to solve performance
problems.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
8
This book will change the way
you think about performance!
• The Goal: A Process
of Ongoing
Improvement
• Eliyahu Goldratt, Jeff
Cox
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
9
‘A Practitioners Guide to
Optimizing Response Time’
• Optimizing Oracle
Performance
• Cary Millsap
• with Jeff Holt
– O’Reilly
• www.hotsos.com
• www.method-r.com
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
10
Aphorism
Performance is exactly
what the user
perceives it to be. No
more, no less.
Collaborate 08: SQL*Trace &
Execution Plans
Performance is ‘poor’
when the user’s
perception does not
match their
expectation.
www.go-faster.co.uk
11
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.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
12
What is SQL trace?
• Session or database level
• Oracle shadow process writes to a text file
in user_dump_dest.
• Trace file contains
–
–
–
–
User and recursive SQL statements
Execution plan, physical & logical reads
Timing information
Wait and bind information (optional)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
13
What is SQL trace?
• First appeared in Oracle 6.
• More instrumentation added at each release.
• Text file, not a very friendly format, but it
can be read
– And sometimes that is necessary
– Metalink note 39817.1 details structure of trace
files
• Usually process it with tkprof
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
14
So what should I 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.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
15
Initialisation parameters
•
•
•
•
•
timed_statistics = TRUE
user_dump_dest = '<directory name>'
max_dump_file_size = <size>
_trace_files_public = TRUE
trace_file_identifier = '<string>'
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
16
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
Can be set at session level
Defaults to true since Oracle 9i
Leave it set to true
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
17
max_dump_file_size
• Be careful that your trace files are not
truncated.
– look at tail for message
• DUMP FILE SIZE IS LIMITED
• Unless the file system fills up!
– 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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
18
_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.
• Alternative: change permissions on udump
directory and set the set uid bit
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
19
tracefile_identifier = <string>
• Set at init.ora or session 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.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
20
tracefile_identifier = <string>
ALTER SESSION SET TRACE_FILE_IDENTIFIER =
‘nVision_Report_NVSRUN_159’;
/u01/app/oracle/admin/F84SP1/udump/
f84sp1_ora_41776_nVision_Report_NVSRUN_159.trc
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
21
Unsupported ways 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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
22
Database trace
• Probably not a good idea
– Initialisation File
• sql_trace = TRUE
• event = '10046 trace name context forever, level 4';
– SQL Command
• ALTER SYSTEM SET SQL_TRACE=TRUE;
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
23
Lots of unsupported ways to enable
trace
• Session level
DBMS_SESSION.SET_SQL_TRACE(TRUE);
DBMS_SUPPORT.START_TRACE(waits=>TRUE,
binds=>TRUE);
DBMS_SUPPORT.START_TRACE_IN_SESSION(sid,
serial#, waits=>TRUE, binds=> TRUE);
DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(sid,
serial#, sql_trace=>TRUE);
DBMS_SYSTEM.SET_EV(sid, serial, ev=>10046,
le=12, '');
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
24
New in Oracle 10g
• But, this is the only supported method
DBMS_MONITOR.SESSION_TRACE_ENABLE
(
si NUMBER,
-- SID (defaults to current
-- session)
se NUMBER,
-- Serial Number (can be 0)
waits BOOLEAN, -- Include waits (default FALSE)
binds BOOLEAN -- Include binds (default FALSE)
);
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
25
New in Oracle 10g
• Enable on event
– Like a watch point in a debugger
DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE (
client_id VARCHAR2);
DBMS_MONITOR.SERV_MOD_ACT_STAT_ENABLE(
service_name VARCHAR2,
module_name VARCHAR2,
action_name VARCHAR2,
instance_name VARCHAR2);
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
26
Using logon triggers to enable
SQL trace
• Login trigger to trace from the very
beginning.
CREATE OR REPLACE TRIGGER
sysadm.trace_logon_sysadm
AFTER LOGON ON sysadm.schema
BEGIN
sys.dbms_monitor.session_trace_enable
(waits=>TRUE);
END;
/
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
27
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 != 'PSJob'
AND new.prcsname = ‘GPPDPRUN’
AND new.begindttm <=
TO_DATE('200411031800','YYYYMMDDHH24MI'))
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
28
Using triggers to enable SQL
trace (ii)
BEGIN
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||'''';
sys.dbms_monitor.session_trace_enable
(waits=>TRUE);
END;
/
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
29
What is in the SQL trace file
• Trace Sections
• See Metalink Note 39817.1 for details
– DBMS_APPLICATION_INFO settings
– Cursors
– Operations
• Parse, exec, fetch, (sort) unmap
– Errors
– Stat
• Execution Plans
– Xctend
• End of transaction
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
30
SQL trace file sections
• With event 10046
– Binds
• (level 4)
– Waits
• (level 8)
• Timings
– microsecond from Oracle 9
– centisecond timings (Oracle 7 & 8)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
31
SQL trace file contents
Dump file
d:\oracle\product\10.2.0\admin\hcm89\udump\hcm89_ora_
2020_application_engine_psquery_1925.trc
Tue Apr 15 22:51:29 2008
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release
10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU
: 2 - type 586
Process Affinity
: 0x00000000
Memory (Avail/Total): Ph:283M/2047M,
Ph+PgF:2174M/3943M, VA:1662M/2047M
Instance name: hcm89
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
32
SQL trace file contents
Redo thread mounted by this instance: 1
Oracle process number: 24
Windows thread id: 2020, image: ORACLE.EXE (SHAD)
*** 2008-04-15 22:51:29.343
*** SERVICE NAME:(HCM89) 2008-04-15 22:51:29.296
*** SESSION ID:(142.164) 2008-04-15 22:51:29.296
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
33
SQL trace file contents
PARSING IN CURSOR #1 len=58 dep=0 uid=39 oct=3 lid=39 tim=343032899686
hv=1439785590 ad='6ba736b0'
SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS'
END OF STMT
PARSE #1:c=0,e=63,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=343032899681
BINDS #1:
EXEC #1:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=343032899870
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1413697536
#bytes=1 p3=0 obj#=-1 tim=343032899919
FETCH #1:c=0,e=54,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,tim=343032900056
WAIT #1: nam='SQL*Net message from client' ela= 19090 driver
id=1413697536 #bytes=1 p3=0 obj#=-1 tim=343032919230
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=36635 op='TABLE ACCESS BY INDEX
ROWID PSVERSION (cr=2 pr=0 pw=0 time=53 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=36636 op='INDEX UNIQUE SCAN
PS_PSVERSION (cr=1 pr=0 pw=0 time=25 us)'
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
34
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
35
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: 0
Optimizer mode: ALL_ROWS
Parsing user id: 39
Rows
Row Source Operation
------- --------------------------------------------------1 TABLE ACCESS BY INDEX ROWID PSVERSION (cr=2 pr=0 pw=0 time=53 us)
1
INDEX UNIQUE SCAN PS_PSVERSION (cr=1 pr=0 pw=0 time=25 us)(object id
36636)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
36
Row source statistics
• From Oracle 9.2.0.2
ALTER SESSION
SET STATISTICS_LEVEL = ALL;
–
–
–
–
Statistics added to SQL Trace stat line
Object Names instead of IDs
Appears in tkprof output
Performance overhead
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
37
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
0
89622
---------89622
38
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)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
39
Limitations TKPROF
• tkprof output does not show bind variable
values
– You have to look in the raw trace file
– Or use a different profiler
• tkprof only reports the first execution plan
for each cursor
• There are other profilers
– Both commercial and freeware
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
40
SQL*Plus and Autotrace
EXPLAIN PLAN FOR
SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS';
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
Plan hash value: 336040498
-------------------------------------------------------------------------------------------| Id | Operation
| Name
| Rows | Bytes | Cost (%CPU)| Time
|
-------------------------------------------------------------------------------------------|
0 | SELECT STATEMENT
|
|
1 |
7 |
1
(0)| 00:00:01 |
|
1 | TABLE ACCESS BY INDEX ROWID| PSVERSION
|
1 |
7 |
1
(0)| 00:00:01 |
|* 2 |
INDEX UNIQUE SCAN
| PS_PSVERSION |
1 |
|
0
(0)| 00:00:01 |
--------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
--------------------------------------------------2 - access("OBJECTTYPENAME"='SYS')
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
41
SQL*Plus and Autotrace
EXPLAIN PLAN FOR
SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = :BIND;
SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
Plan hash value: 336040498
-------------------------------------------------------------------------------------------| Id | Operation
| Name
| Rows | Bytes | Cost (%CPU)| Time
|
-------------------------------------------------------------------------------------------|
0 | SELECT STATEMENT
|
|
1 |
7 |
1
(0)| 00:00:01 |
|
1 | TABLE ACCESS BY INDEX ROWID| PSVERSION
|
1 |
7 |
1
(0)| 00:00:01 |
|* 2 |
INDEX UNIQUE SCAN
| PS_PSVERSION |
1 |
|
0
(0)| 00:00:01 |
--------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
--------------------------------------------------2 - access("OBJECTTYPENAME"=:BIND)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
42
/*+ gather_plan_statistics */
SELECT /*+gather_plan_statistics*/ COUNT(*) FROM t WHERE a > SYSDATE;
SELECT * FROM table(dbms_xplan.display_cursor(null,
null, 'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------SQL_ID 4xynhdf790u2x, child number 0
------------------------------------select /*+gather_plan_statistics*/ count(*) from t where a > SYSDATE
Plan hash value: 2966233522
------------------------------------------------------------------------------------| Id | Operation
| Name | Starts | E-Rows | A-Rows |
A-Time
| Buffers |
------------------------------------------------------------------------------------|
1 | SORT AGGREGATE
|
|
1 |
1 |
1 |00:00:00.01 |
7 |
|* 2 |
TABLE ACCESS FULL| T
|
1 |
1 |
100 |00:00:00.01 |
7 |
-------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
--------------------------------------------------2 - filter("A">SYSDATE@!)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
43
DBMS_APPLICATION_INFO
• Instrument and Identify your code
– Client_info: Who was logged in
– Module: What program are they running
– Action: What are they doing in that program
• Can query from v$session
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
44
DBMS_APPLICATION_INFO
• Client Info
– Relate database session to human user
– Can then ask the user what they were doing
– 64 characters free format
• Eg.
– EmployeeID_Surname_Firstname_LogonTime
– 00001955_Kurtz_David_20071206_0942
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
45
Module and Action
CREATE OR REPLACE PACKAGE BODY my_package AS
PROCEDURE my_procedure IS
vc_module VARCHAR2(48);
vc_action VARCHAR2(32);
BEGIN
dbms_application_info.read_module(module_name => vc_module,
action_name => vc_action);
dbms_application_info.set_module(module_name
=>'MY_PACKAGE.MY_PROCEDURE', action_name => 'START');
...
dbms_application_info.set_module(module_name => vc_module,
action_name => vc_action);
WHEN OTHERS THEN
dbms_application_info.set_module(module_name => vc_module,
action_name => vc_action);
RAISE;
END my_procedure;
END my_package;
/
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
46
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>
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
47
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?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
48
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
49
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
0
0
---------0
50
Execution plan
(from stat lines, Oracle < 9.2.0.2)
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)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
51
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)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
52
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
53
PP_METHOD <> ' '
2. Start to 3.
draw
Addthe
thequery
joins
EFFDT
PS_CUST_OPTION
(O)
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
PS_CUSTOMER
(C)
RECNAME = 'CUSTOMER'
SETID
PS_SET_CNTRL_REC
(S)
S.SETCNTRLVALUE = I.BUSINESS_UNIT
REF_QUALIFIER_CODE = 'I'
CUST_ID
PS_ITEM
(I)
X.REF_VALUE = I.ITEM
I.ITEM_STATUS = 'O'
PS_PAYMENT_ID_ITEM
(X)
P.DEPOSIT_BU = X.DEPOSIT_BU
P.DEPOSIT_ID = X.DEPOSIT_ID
P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
PS_PP_PAYMENT_TMP
(P)
54
PROCESS_INSTANCE = 212
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)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
55
5. Put the order in the diagram
PP_METHOD <> ' '
EFFDT
PS_CUST_OPTION
(O)
(O)6
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
PS_CUSTOMER
(C)
(C)4
RECNAME = 'CUSTOMER'
SETID
PS_SET_CNTRL_REC
(S)
(S)3
S.SETCNTRLVALUE = I.BUSINESS_UNIT
REF_QUALIFIER_CODE = 'I'
CUST_ID
PS_ITEM
(I)
(I)5
X.REF_VALUE = I.ITEM
I.ITEM_STATUS = 'O'
PS_PAYMENT_ID_ITEM
(X)
(X)2
P.DEPOSIT_BU = X.DEPOSIT_BU
P.DEPOSIT_ID = X.DEPOSIT_ID
P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
PS_PP_PAYMENT_TMP
(P)
(P)1
56
PROCESS_INSTANCE = 212
6. This time, the answer is an
index
CREATE INDEX PSBITEM ON PS_ITEM
(ITEM,
CUST_ID,
BUSINESS_UNIT,
ITEM_STATUS)
TABLESPACE PSINDEX
/
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
57
PP_METHOD <> ' '
EFFDT
PS_CUST_OPTION
(O)
(O)6
New Execution Order
O.SETID = C.REMIT_FROM_SETID
O.CUST_ID = C.REMIT_FROM_CUST_ID
PS_CUSTOMER
(C)
(C)5
RECNAME = 'CUSTOMER'
SETID
PS_SET_CNTRL_REC
(S)
(S)4
S.SETCNTRLVALUE = I.BUSINESS_UNIT
REF_QUALIFIER_CODE = 'I'
CUST_ID
PS_ITEM
(I)
(I)3
X.REF_VALUE = I.ITEM
I.ITEM_STATUS = 'O'
PS_PAYMENT_ID_ITEM
(X)
(X)2
P.DEPOSIT_BU = X.DEPOSIT_BU
P.DEPOSIT_ID = X.DEPOSIT_ID
P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
PS_PP_PAYMENT_TMP
(P)
(P)1
58
PROCESS_INSTANCE = 212
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
0
0
---------0
59
Example 2: Wait Events
• How do you know it’s not the database?
• Event 10046,8 – enable wait information.
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
60
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
558966
0
---------558966
61
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 to client
22510
0.01
SQL*Net message from client
22510
0.44
latch free
5
0.02
free buffer waits
19
1.02
buffer busy waits
1
0.00
log file switch completion
1
0.06
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
Total Waited
-----------1036.26
148.99
0.08
80.41
0.08
4.74
0.00
0.06
62
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 message from client
SQL*Net more data from client
Collaborate 08: SQL*Trace &
Execution Plans
Times
Waited
22264
29138
Max. Wait
---------0.47
0.47
www.go-faster.co.uk
rows
---------0
662676
0
---------662676
Total Waited
-----------88.84
6.69
63
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
645
0
---------645
64
Wait Events
Elapsed times include waiting on following events:
Event waited on
Times
Max. Wait Total Waited
--------------------------Waited ---------- -----------enqueue
658
3.34
1973.10
SQL*Net message from client
27973
1.34
99.10
db file sequential read
1630
0.27
8.67
SQL*Net message to client
27973
0.00
0.05
latch free
2
0.00
0.00
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
65
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?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
66
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
67
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
2657717
3030039
---------5687756
68
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
Total Waited
-----------1.68
2491.24
28.18
5.27
1.54
451.60
49.76
28.97
69
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?)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
4790
2491
1673
626
70
Example 5: 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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
71
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
rows
---------0
0
1117812
---------1117812
72
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)
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
73
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
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
74
Example 6: Transitive Closure
• If A=B and B=C you can infer that A=C
• You and I can, but Oracle can’t do this on
column predicates
• Oracle can do this on value predicates
• If A=1 and A=B, Oracle knows that B=1
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
75
A simple query?
SELECT ... FROM PS_GP_PYE_STAT_WRK S,PS_GP_PYE_PRC_STAT P2,PS_GP_RSLT_ACUM RA
WHERE S.RUN_CNTL_ID=:1
AND S.OPRID=:2
AND S.EMPLID BETWEEN :3 AND :4
AND S.EMPLID=RA.EMPLID
AND S.EMPL_RCD=RA.EMPL_RCD
AND S.GP_PAYGROUP=RA.GP_PAYGROUP
AND S.CAL_ID=RA.CAL_ID
AND P2.EMPLID=RA.EMPLID
AND P2.EMPL_RCD=RA.EMPL_RCD
AND P2.GP_PAYGROUP=RA.GP_PAYGROUP
AND P2.CAL_ID=RA.CAL_ID
AND P2.CAL_RUN_ID=RA.CAL_RUN_ID
AND P2.ORIG_CAL_RUN_ID=RA.ORIG_CAL_RUN_ID
AND S.PRD_TYPE='R'
AND S.RSLT_SEG_NUM=RA.RSLT_SEG_NUM
AND S.PRIOR_VER_NUM=P2.RSLT_VER_NUM
AND S.PRIOR_REV_NUM=P2.RSLT_REV_NUM
AND RA.ACM_PRD_OPTN='1';
Collaborate 08: SQL*Trace &
www.go-faster.co.uk
76
Execution Plans
A three table join
RUN_CNTL_ID=:1
OPRID=:2
:3 <= `EMPLID <= :4
PRD_TYPE='R'
PS_GP_PYE_STAT_WRK
(S) 1
S.PRIOR_VER_NUM=P2.RSLT_VER_NUM
EMPLID, EMPL_RCD, GP_PAYGROUP,
S.PRIOR_REV_NUM=P2.RSLT_REV_NUM
CAL_ID, RSLT_SEG_NUM
PS_GP_PYE_PRC_STAT
(P2) 3
EMPLID, EMPL_RCD, GP_PAYGROUP,
CAL_RUN_ID, ORIG_CAL_RUN_ID,
PS_GP_RSLT_ACUM
(RA) 2
CAL_ID, RSLT_SEG_NUM
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
77
ACM_PRD_OPTN='1'
Index on GP_RSLT_ACUM
CREATE UNIQUE INDEX PS_GP_RSLT_ACUM ON PS_GP_RSLT_ACUM
(EMPLID,
CAL_RUN_ID,
EMPL_RCD,
GP_PAYGROUP,
CAL_ID,
ORIG_CAL_RUN_ID,
RSLT_SEG_NUM,
PIN_NUM,
EMPL_RCD_ACUM,
ACM_FROM_DT,
ACM_THRU_DT,
SLICE_BGN_DT,
SLICE_END_DT,
SEQ_NUM8) ...
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
78
Explicitly add implicit joins
AND
AND
AND
AND
P2.EMPLID=S.EMPLID
P2.EMPL_RCD=S.EMPL_RCD
P2.GP_PAYGROUP=S.GP_PAYGROUP
P2.CAL_ID=S.CAL_ID
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
79
With the extra index
RUN_CNTL_ID=:1
OPRID=:2
:3 <= `EMPLID <= :4
PRD_TYPE='R'
PS_GP_PYE_STAT_WRK
(S) 1
EMPLID, EMPL_RCD, GP_PAYGROUP, CAL_ID
EMPLID, EMPL_RCD, GP_PAYGROUP,
S.PRIOR_VER_NUM=P2.RSLT_VER_NUM
CAL_ID, RSLT_SEG_NUM
S.PRIOR_REV_NUM=P2.RSLT_REV_NUM
PS_GP_PYE_PRC_STAT
(P2) 2
EMPLID, EMPL_RCD, GP_PAYGROUP,
CAL_RUN_ID, ORIG_CAL_RUN_ID,
PS_GP_RSLT_ACUM
(RA) 3
CAL_ID, RSLT_SEG_NUM
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
80
ACM_PRD_OPTN='1'
Index on GP_RSLT_ACUM
CREATE UNIQUE INDEX PS_GP_RSLT_ACUM ON PS_GP_RSLT_ACUM
(EMPLID,
CAL_RUN_ID,
EMPL_RCD,
GP_PAYGROUP,
CAL_ID,
ORIG_CAL_RUN_ID,
RSLT_SEG_NUM,
PIN_NUM,
EMPL_RCD_ACUM,
ACM_FROM_DT,
ACM_THRU_DT,
SLICE_BGN_DT,
SLICE_END_DT,
SEQ_NUM8) ...
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
81
Conclusion
• How to think about performance issues
• IDENTIFY YOUR BOTTLENECKS
• SQL Trace
– What to trace, How to enable, What’s in it?
• Tkprof
– What can it tell you? When does it mislead?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
82
Questions?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
83
An introduction to SQL*Trace,
TKPROF and Execution Plans
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
Questions?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
85
Conclusion
• How to think about performance issues
• IDENTIFY YOUR BOTTLENECKS
• SQL Trace
– What to trace, How to enable, What’s in it?
• Tkprof
– What can it tell you? When does it mislead?
Collaborate 08: SQL*Trace &
Execution Plans
www.go-faster.co.uk
86