Tuning with Oracle

1
Tuning with Oracles SQL Trace

• David Kurtz
• Go-Faster Consultancy Ltd.
• david_at_go-faster.co.uk
• www.go-faster.co.uk

2
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

3
Who am I?

• DBA
• Independent consultant
• Performance tuning

4
Tuning with Oracles SQL Trace

• Overview of Tuning
• Explain Plan
• Enabling SQL Trace
• TKPROF
• Interpreting Execution Plans

5
Rules of Engagement

• Interrupt me
• if you think I have got something wrong
• if you have a question
• if you cant hear me

6
What is Tuning?

• It is a much abused term
• What does a person mean when they say Tuning

7
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

8
Oracle Designing and Tuning for Performance Manual

• Chapters
• 4. The Optimiser
• 5. Using Explain Plan
• 6. Using SQL Trace and TKPROF

9
When should I start to Tune?

• NOW is already too late

from Oracle Designing and Tuning for Performance
10
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

11
Tuning is a search for lost time

• Identify problem SQL
• Find out why it is a problem
• SQL execution plan

12
Explain plan

• Explain plan for ltsql statementgt
• PLAN_TABLE
• set autotrace on

13
Rule -v- Cost Based Optimiser

• select /RULE/
• from dual
• Execution Plan
• ---------------------------
• 0 SELECT STATEMENT OptimizerHINT RULE
• 1 0 TABLE ACCESS (FULL) OF 'DUAL'

• select /ALL_ROWS/
• from dual
• Execution Plan
• ---------------------------
• 0 SELECT STATEMENT OptimizerHINT ALL_ROWS
  (Cost1 Card1 Bytes2)
• 1 0 TABLE ACCESS (FULL) OF 'DUAL'
• (Cost1 Card1 Bytes2)

14
SQL Trace

• Whole database
• SQL_TRACETRUE
• Current Session
• ALTER SESSION SET SQL_TRACETRUE
• sys.dbms_session.set_sql_trace(true)
• A different session
• sys.dbms_system.set_sql_trace_in_session
  (ltsidgt,ltserialgt,TRUE)

15
USER_DUMP_DEST

• Trace file written to directory
• USER_DUMP_DEST
• Default
• ORACLE_HOME/rdbms/log/
• System level
• ALTER SYSTEM SET USER_DUMP_DESTnewdir

16
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

17
Timed Statistics

• Enable to get statement and other timings
• Initialisation file
• TIMED_STATISTICSTRUE
• Ad-hoc
• ALTER SYSTEM SET TIMED_STATISTICSTRUE
• Small performance overhead

18
Trace File (Unix)

• Difficult to read, but useful information
• Dump file /PS/oracle/app/oracle/product/8.0.5/rdbm
  s/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

19
Trace File (NT)

• Dump file c\user\ppt\tuning with Oracle
  Trace\demo\ORA00298.TRC
• Tue May 16 200247 2000
• ORACLE V8.1.6.0.0 - Production vsnsta0
• vsnsqle vsnxtr3
• 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

20
Trace file

• Lists every statement
• PARSING IN CURSOR 1 len33 dep0 uid21 oct42
  lid21 tim1118983 hv3176041220 ad'809c49a4'
• ALTER SESSION SET SQL_TRACETRUE
• END OF STMT
• EXEC 1c0,e2,p0,cr0,cu0,mis1,r0,dep0,og4
  ,tim1118983

21
Trace file

• Contains the execution plan
• END OF STMT
• PARSE 1c44,e45,p42,cr1821,cu4,mis1,r0,dep
  0,og4,tim1120108
• 1999.02.25.16.17.58.000
• EXEC 1c15661,e16023,p164769,cr3981545,cu0,m
  is0,r0,dep0,og4,tim1136131
• EXEC 2c0,e3,p4,cr1,cu3,mis0,r1,dep0,og4
  ,tim1136134
• STAT 1 id1 cnt0 pid0 pos0 obj0 op'SORT
  UNIQUE '
• STAT 1 id2 cnt0 pid1 pos1 obj0 op'FILTER '
• STAT 1 id3 cnt0 pid2 pos1 obj0 op'NESTED
  LOOPS '
• STAT 1 id4 cnt8 pid3 pos1 obj0 op'NESTED
  LOOPS '
• STAT 1 id5 cnt1000040 pid4 pos1 obj0
  op'NESTED LOOPS '
• STAT 1 id6 cnt360 pid5 pos1 obj0 op'NESTED
  LOOPS '
• STAT 1 id7 cnt10 pid6 pos1 obj0 op'NESTED
  LOOPS '
• STAT 1 id8 cnt10 pid7 pos1 obj10009
  op'TABLE ACCESS BY INDEX ROWID PS_PP_PAYMENT_TMP
  
• ...

22
TKPROF

• Processes the trace file
• removes recursive SQL
• generate execution plans
• aggregate duplicates
• sort by criteria
• top n statements

23
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

24
TKPROF Command

• Usage tkprof tracefile outputfile explain
  table
• print insert sys sort
  
• tableschema.tablename Use 'schema.tablename'
  with 'explain' option.
• explainuser/password Connect to ORACLE and
  issue EXPLAIN PLAIN.
• printinteger List only the first 'integer'
  SQL statements.
• aggregateyesno
• insertfilename List SQL statements and data
  inside INSERT statements.
• sysno TKPROF does not list SQL
  statements run as user SYS.
• recordfilename Record non-recursive
  statements found in the trace file.
• sortoption 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

25
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 lt
• P.PAYMENT_DT ) AND O.PP_METHOD ltgt ' '
  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

26
Statistics

• count number of times OCI procedure was
  executed
• cpu cpu time in seconds executing
• elapsed elapsed time in seconds executing
• disk number of physical reads of buffers
  from disk
• query number of buffers gotten for
  consistent read
• current number of buffers gotten in current
  mode (usually for update)
• rows number of rows processed by the fetch
  or execute call
• call count cpu elapsed disk
  query current rows
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• Parse 1 0.31 0.33 4
  0 4 0
• Execute 1 156.61 160.23 164769
  3981545 0 0
• Fetch 0 0.00 0.00 0
  0 0 0
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• total 2 156.92 160.56 164773
  3981545 4 0

27
Execution plan (Oracle 8.1 only)

• Rows Execution Plan
• ------- -----------------------------------------
  ----------
• 0 INSERT STATEMENT GOAL CHOOSE
• 0 SORT (UNIQUE)
• 0 FILTER
• 0 NESTED LOOPS
• 8 NESTED LOOPS
• 1000040 NESTED LOOPS
• 360 NESTED LOOPS
• 10 NESTED LOOPS
• 10 TABLE ACCESS BY INDEX ROWID
  PS_PP_PAYMENT_TMP
• 11 INDEX (RANGE SCAN) (object id
  9329)
• 20 INDEX (RANGE SCAN) OF (object id
  8105)
• 360 TABLE ACCESS (BY INDEX ROWID) OF
  'PS_SET_CNTRL_REC'
• 370 INDEX (RANGE SCAN) OF (object id
  12020)
• 1000040 TABLE ACCESS (BY INDEX ROWID) OF
  'PS_CUSTOMER'
• 1000400 INDEX (RANGE SCAN) OF (object id
  4751)
• 1000048 INDEX (RANGE SCAN) OF 'PSITEM'
  (NON-UNIQUE)
• 8 TABLE ACCESS (BY INDEX ROWID) OF
  'PS_CUST_OPTION'

28
Execution plan (if you connect TKPROF to the
database)

• Rows Execution Plan
• ------- -----------------------------------------
  ----------
• 0 INSERT STATEMENT GOAL CHOOSE
• 0 SORT (UNIQUE)
• 0 FILTER
• 0 NESTED LOOPS
• 8 NESTED LOOPS
• 1000040 NESTED LOOPS
• 360 NESTED LOOPS
• 10 NESTED LOOPS
• 10 TABLE ACCESS (BY INDEX ROWID) OF
  
• 'PS_PP_PAYMENT_TMP'
• 11 INDEX (RANGE SCAN) OF
  'PSAPP_PAYMENT_TMP'
• (NON-UNIQUE)
• 20 INDEX (RANGE SCAN) OF
  'PSAPAYMENT_ID_ITEM'
• (NON-UNIQUE)
• 360 TABLE ACCESS (BY INDEX ROWID) OF
  'PS_SET_CNTRL_REC'
• 370 INDEX (RANGE SCAN) OF
  'PSBSET_CNTRL_REC'
• (NON-UNIQUE)

29
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'
  

30
2. Start to draw the query
31
3. Put the joins in
32
4. Get the order from the plan

• 0 FILTER
• 0 NESTED LOOPS
• 8 NESTED LOOPS
• 1000040 NESTED LOOPS
• 360 NESTED LOOPS
• 10 NESTED LOOPS
• 10 (1)TABLE ACCESS (BY INDEX ROWID)
  OF
• 'PS_PP_PAYMENT_TMP'
• 11 INDEX (RANGE SCAN) OF
  'PSAPP_PAYMENT_TMP'
• (NON-UNIQUE)
• 20 (2)INDEX (RANGE SCAN) OF
  'PSAPAYMENT_ID_ITEM'
• (NON-UNIQUE)
• 360 (3)TABLE ACCESS (BY INDEX ROWID)
  OF 'PS_SET_CNTRL_REC'
• 370 INDEX (RANGE SCAN) OF
  'PSBSET_CNTRL_REC'
• (NON-UNIQUE)
• 1000040 (4)TABLE ACCESS (BY INDEX ROWID)
  OF 'PS_CUSTOMER'
• 1000400 INDEX (RANGE SCAN) OF
  'PSCUSTOMER' (NON-UNIQUE)
• 1000048 (5)INDEX (RANGE SCAN) OF 'PSITEM'
  (NON-UNIQUE)
• 8 (6)TABLE ACCESS (BY INDEX ROWID) OF
  'PS_CUST_OPTION'

33
5. Put the order in the diagram
34
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)
• /

35
New execution order
36
Statistics

• Before
• call count cpu elapsed disk
  query current rows
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• Parse 1 0.31 0.33 4
  0 4 0
• Execute 1 156.61 160.23 164769
  3981545 0 0
• Fetch 0 0.00 0.00 0
  0 0 0
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• total 2 156.92 160.56 164773
  3981545 4 0
• After
• call count cpu elapsed disk
  query current rows
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• Parse 1 0.35 2.56 3
  0 3 0
• Execute 1 0.03 0.05 38
  289 3 0
• Fetch 0 0.00 0.00 0
  0 0 0
• ------- ------ -------- ---------- ----------
  ---------- ---------- ----------
• total 2 0.38 2.61 41
  289 6 0

37
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?

38
How to SQL_Trace PeopleSoft?

• Client
• Query/Crystal Database Agent
• SQR
• Cobol
• AE
• nVision

39
Client

• Multithreaded
• 2-tier, 3-tier
• Client trace - SQLcleanup.exe
• SQL Script
• Work in SQLPlus
• Small application server
• no PSQCKSRV or PSQRYSRV
• enable trace on PSAPPSRV

40
PS/Query, Crystal, Database Agent

• Trace Application Server
• PSQRYSRV
• Cut and paste SQL PS/Query
• work in SQLPlus

41
nVision

• Trace PSQRYSRV
• Client trace SQLcleanup.exe
• Cut and paste the statement directly

42
Mass Change
43
Application Engine
44
SQR

• session.sqc
• begin-sql
• ALTER SESSION SET SQL_TRACETRUE
• end-SQL

45
Cobol

• Difficult to add extra statements
• Batch
• Initiated via Process Scheduler
• Data driven agent
• Table of requests
• Each request has a status

46
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 lt TO_DATE(16062000,DDMMYYYY)
  )
• begin
• sys.dbms_session.set_sql_trace(true)
• exception when others then null
• end
• /

47
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','Databas
  e Agent'))
• begin
• insert into dmk_trace_log
• (prcsinstance, oracle_shadow, timestamp)
• select new.prcsinstance, p.spid, sysdate
• from vsession s, vprocess p
• where s.sid (select sid from vmystat where
  rownum 1)
• and s.paddr p.addr
• sys.dbms_session.set_sql_trace(true)
• exception when others then null
• end
• /

48
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','Databas
  e Agent'))
• declare
• pragma autonomous_transaction
• begin
• insert into dmk_trace_log
• (prcsinstance, oracle_shadow, timestamp)
• select new.prcsinstance, p.spid, sysdate
• from vsession s, vprocess p
• where s.sid (select sid from vmystat 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
• /

49
Tuning with Oracles SQL Trace

• Tuning
• SQL Trace
• TKPROF
• Explain Plan
• Graphical Technique
• Techniques for enabling SQL Trace

50
Any Questions?
51
Tuning with Oracles SQL Trace

• David Kurtz
• Go-Faster Consultancy Ltd.
• david_at_go-faster.co.uk
• www.go-faster.co.uk