Transcript Tuning with Oracle’s SQL Trace David Kurtz Go-Faster Consultancy Ltd. [email protected] www.go-faster.co.uk Message from the SIG management • Keep filling in the critique forms • Keep suggesting.

Tuning with Oracle’s SQL Trace
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
1
Message from the SIG
management
• Keep filling in the critique forms
• Keep suggesting topics
– This is session was a requested topic
• Offer to talk on topic about which you know
2
Who am I?
• DBA
– Independent consultant
– Performance tuning
3
Tuning with Oracle’s SQL Trace
•
•
•
•
•
Overview of Tuning
Explain Plan
Enabling SQL Trace
TKPROF
Interpreting Execution Plans
4
Rules of Engagement
• Interrupt me:
– if you think I have got something wrong
– if you have a question
– if you can’t hear me
5
What is Tuning?
• It is a much abused term
• What does a person mean when they say
‘Tuning’
6
Oracle Designing and Tuning for
Performance Manual
• New name in Oracle 8i
• Used to be the ‘Tuning’ manual
• A good place to start
• Always there
• Free
7
Oracle Designing and Tuning for
Performance Manual
• Chapters
4. The Optimiser
5. Using Explain Plan
6. Using SQL Trace and TKPROF
8
When should I start to Tune?
• NOW is already too late
9
from ‘Oracle Designing and Tuning for Performance’
Tuning occurs at Different Levels
•
•
•
•
•
•
•
•
•
•
business design
data design
application design
logical structure of the database
database operations
access paths
memory allocation
I/O and physical structure
resource contention
platform
10
Tuning is a search for lost time
• Identify problem SQL
• Find out why it is a problem
– SQL execution plan
11
Explain plan
• Explain plan for
<sql statement>
– PLAN_TABLE
• set autotrace on
12
Rule -v- Cost Based Optimiser
select /*+RULE*/ *
from dual;
select /*+ALL_ROWS*/ *
from dual;
Execution Plan
-------------------------0
SELECT STATEMENT
Optimizer=HINT: RULE
Execution Plan
-------------------------0
SELECT STATEMENT
Optimizer=HINT:
ALL_ROWS (Cost=1 Card=1
Bytes=2)
1
0
TABLE ACCESS
(FULL) OF 'DUAL'
1
0
TABLE ACCESS
(FULL) OF 'DUAL'
(Cost=1 Card=1 Bytes=2)
13
SQL Trace
• Whole database
– SQL_TRACE=TRUE
• Current Session
– ALTER SESSION SET SQL_TRACE=TRUE;
– sys.dbms_session.set_sql_trace(true)
• A different session
– sys.dbms_system.set_sql_trace_in_session
(<sid>,<serial#>,TRUE);
14
USER_DUMP_DEST
• Trace file written to directory
– USER_DUMP_DEST
• Default
– $ORACLE_HOME/rdbms/log/
• System level
– ALTER SYSTEM SET
USER_DUMP_DEST=newdir
15
MAX_DUMP_FILE_SIZE
• Maximum size of trace file
– Kbytes / OS blocks
– Shadow process will stop writing when
maximum reached
– grep "DUMP FILE SIZE IS LIMITED”
• Beware
– Truncated trace file
– Full File System
16
Timed Statistics
• Enable to get statement and other timings
• Initialisation file
– TIMED_STATISTICS=TRUE
• Ad-hoc
– ALTER SYSTEM SET
TIMED_STATISTICS=TRUE;
• Small performance overhead
17
Trace File (Unix)
• Difficult to read, but useful information
Dump file
/PS/oracle/app/oracle/product/8.0.5/rdbms/log/psperf_ora_20437.trc
Oracle8 Enterprise Edition Release 8.0.5.0.0 - Production
PL/SQL Release 8.0.5.0.0 - Production
ORACLE_HOME = /PS/oracle/app/oracle/product/8.0.5
System name: SunOS
Node name:
hqmain01
Release:
5.6
Version:
Generic_105181-08
Machine:
sun4u
Instance name: PSPERF
Redo thread mounted by this instance: 1
Oracle process number: 30
Unix process pid: 20437, image: oraclePSPERF
*** SESSION ID:(30.3900) 1999.02.25.16.15.06.000
18
Trace File (NT)
Dump file c:\user\ppt\tuning with Oracle Trace\demo\ORA00298.TRC
Tue May 16 20:02:47 2000
ORACLE V8.1.6.0.0 - Production vsnsta=0
vsnsql=e vsnxtr=3
Windows NT Version 4.0 Service Pack 6, CPU type 586
Oracle8i Enterprise Edition Release 8.1.6.0.0 - Production
With the Partitioning option
JServer Release 8.1.6.0.0 - Production
Windows NT Version 4.0 Service Pack 6, CPU type 586
Instance name: f75do81
Redo thread mounted by this instance: 1
Oracle process number: 9
Windows thread id: 298, image: ORACLE.EXE
19
Trace file
• Lists every statement
PARSING IN CURSOR #1 len=33 dep=0 uid=21 oct=42 lid=21
tim=1118983 hv=3176041220 ad='809c49a4'
ALTER SESSION SET SQL_TRACE=TRUE
END OF STMT
EXEC #1:c=0,e=2,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1118983
20
Trace file
• Contains the execution plan
END OF STMT
PARSE #1:c=44,e=45,p=42,cr=1821,cu=4,mis=1,r=0,dep=0,og=4,tim=1120108
*** 1999.02.25.16.17.58.000
EXEC #1:c=15661,e=16023,p=164769,cr=3981545,cu=0,mis=0,r=0,dep=0,og=4,tim=1136131
EXEC #2:c=0,e=3,p=4,cr=1,cu=3,mis=0,r=1,dep=0,og=4,tim=1136134
STAT #1 id=1 cnt=0 pid=0 pos=0 obj=0 op='SORT UNIQUE '
STAT #1 id=2 cnt=0 pid=1 pos=1 obj=0 op='FILTER '
STAT #1 id=3 cnt=0 pid=2 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=4 cnt=8 pid=3 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=5 cnt=1000040 pid=4 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=6 cnt=360 pid=5 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=7 cnt=10 pid=6 pos=1 obj=0 op='NESTED LOOPS '
STAT #1 id=8 cnt=10 pid=7 pos=1 obj=10009 op='TABLE ACCESS BY INDEX ROWID
PS_PP_PAYMENT_TMP ’
...
21
TKPROF
• Processes the trace file
–
–
–
–
–
removes recursive SQL
generate execution plans
aggregate duplicates
sort by criteria
top n statements
22
Plan Table
• $ORACLE_HOME/rdbms/admin/
utlxplan.sql
– builds plan table
• either make it local to a user,
• or create a public synonym and issue grants
• $ORACLE_HOME/rdbms/admin/
utltkprf.sql
23
TKPROF Command
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
table=schema.tablename
Use 'schema.tablename' with 'explain=' option.
explain=user/password
Connect to ORACLE and issue EXPLAIN PLAIN.
print=integer
List only the first 'integer' SQL statements.
aggregate=yes|no
insert=filename List SQL statements and data inside INSERT statements.
sys=no
TKPROF does not list SQL statements run as user SYS.
record=filename Record non-recursive statements found in the trace file.
sort=option
Set of zero or more of the following sort options:
...
execnt number of execute was called
execpu cpu time spent executing
exeela elapsed time executing
exedsk number of disk reads during execute
exeqry number of buffers for consistent read during execute
execu
number of buffers for current read during execute
exerow number of rows processed during execute
exemis number of library cache misses during execute
...
24
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
25
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
rows
---------0
0
0
---------0
26
Execution plan (Oracle 8.1 only)
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)
27
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)
28
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
29
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
30
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'
ITEM_STATUS = 'O'
EM
= I.IT
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
PS_PP_PAYMENT_TMP
P
PROCESS_INSTANCE
= 212
31
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)
32
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)
REF_QUALIFIER_CODE = 'I'
= I.IT
ITEM_STATUS = 'O'
EM
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
PS_PP_PAYMENT_TMP
P (1)
PROCESS_INSTANCE
= 212
33
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)
/
34
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)
REF_QUALIFIER_CODE = 'I'
ITEM_STATUS = 'O'
EM
= I.IT
DEPOSIT_BU
DEPOSIT_ID
PAYMENT_SEQ_NUM
PS_PP_PAYMENT_TMP
P (1)
PROCESS_INSTANCE
= 212
35
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
rows
---------0
0
0
---------0
36
Theory & Practice
•
•
•
•
•
Tuning
Explain Plan
SQL Trace
TKPROF
Graphical Technique
• How and what to trace
a real system?
• Do you have access to
the source code?
• Can you alter the
code?
37
How to SQL_Trace PeopleSoft?
•
•
•
•
•
•
Client
Query/Crystal & Database Agent
SQR
Cobol
AE
nVision
38
Client
• Multithreaded
• 2-tier, 3-tier
– Client trace - SQLcleanup.exe
• SQL Script
• Work in SQL*Plus
– Small application server
• no PSQCKSRV or PSQRYSRV
• enable trace on PSAPPSRV
39
PS/Query, Crystal, Database
Agent
• Trace Application Server
– PSQRYSRV
• Cut and paste SQL PS/Query
– work in SQL*Plus
40
nVision
• Trace PSQRYSRV
• Client trace & SQLcleanup.exe
• Cut and paste the statement directly
41
Mass Change
42
Application Engine
43
SQR
• session.sqc
begin-sql
ALTER SESSION SET SQL_TRACE=TRUE
end-SQL
44
Cobol
• Difficult to add extra statements
• Batch
• Initiated via Process Scheduler
– Data driven agent
– Table of requests
– Each request has a status
45
Cobol
• Trigger on process request table
create or replace trigger sysadm.set_trace
before update of runstatus on sysadm.psprcsrqst
for each row
when (new.runstatus = 7 and old.runstatus != 7
and new.prcstype = 'COBOL SQL'
and new.prcsname = 'GLPJEDIT'
and new.oprid = 'VP1'
and new.servernamerqst = 'PSUNX'
and new.rqstdttm <= TO_DATE(‘16062000’,’DDMMYYYY’))
begin
sys.dbms_session.set_sql_trace(true);
exception when others then null;
end;
/
46
Trigger
• with log
create or replace trigger sysadm.set_trace
before update of runstatus on sysadm.psprcsrqst
for each row
when (new.runstatus = 7 and old.runstatus != 7 and not new.prcstype
IN('Crystal','PSJob','Database Agent'))
begin
insert into dmk_trace_log
(prcsinstance, oracle_shadow, timestamp)
select :new.prcsinstance, p.spid, sysdate
from
v$session s, v$process p
where s.sid = (select sid from v$mystat where rownum = 1)
and
s.paddr = p.addr;
sys.dbms_session.set_sql_trace(true);
exception when others then null;
end;
/
47
Autonomous Trigger
• New in Oracle 8.1
create or replace trigger sysadm.set_trace
before update of runstatus on sysadm.psprcsrqst for each row
when (new.runstatus = 7 and old.runstatus != 7 and not new.prcstype
IN('Crystal','PSJob','Database Agent'))
declare
pragma autonomous_transaction;
begin
insert into dmk_trace_log
(prcsinstance, oracle_shadow, timestamp)
select :new.prcsinstance, p.spid, sysdate
from
v$session s, v$process p
where s.sid = (select sid from v$mystat where rownum = 1)
and
s.paddr = p.addr;
sys.dbms_session.set_sql_trace(true);
commit; --only allowed & mandatory in autonomous trigger
exception when others then null;
end;
/
48
Tuning with Oracle’s SQL Trace
•
•
•
•
•
•
Tuning
SQL Trace
TKPROF
Explain Plan
Graphical Technique
Techniques for enabling SQL Trace
49
Any Questions?
50
Tuning with Oracle’s SQL Trace
David Kurtz
Go-Faster Consultancy Ltd.
[email protected]
www.go-faster.co.uk
51