An introduction to SQL*Trace, TKPROF and Execution Plans

Download Report

Transcript An introduction to SQL*Trace, TKPROF and Execution Plans

An introduction to SQLTrace, TKPROF and Execution Plans*

David Kurtz Go-Faster Consultancy Ltd.

[email protected]

www.go-faster.co.uk

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

Who am I?

• • • • DBA – Independent consultant System Performance tuning – PeopleSoft ERP – Oracle RDBMS UK Oracle User Group – Unix SIG Oak Table – www.oaktable.net

• Book – www.go-faster.co.uk

www.psftdba.com

UKOUG Unix SIG

• Next Meeting – 26 th May 2005 • Midlands – www.ukoug.org

• What are you going to present?

• RDBMS SIG – 15 th March 2005 • Slough • RAC SIG – 16 th June 2005 www.go-faster.co.uk

Agenda

• • • SQL Trace Execution Plans Timing Information • How to use these to solve performance problems.

www.go-faster.co.uk

Motivation

• Performance problems are instinctively routed to the DBA • • Trace can will locate a database problem It will prove that a problems IS NOT a database problem.

www.go-faster.co.uk

YAPP

• R = S + W – Where • • R = response time S = service time • W = wait time – Yet Another Performance Profiling Method • • • Anjo Kolk Shari Yamaguchi Jim Viscusi www.go-faster.co.uk

‘A Practitioners Guide to Optimizing Response Time’

• Optimizing Oracle Performance • Cary Millsap – • O’Reilly with Jeff Holt • www.hotsos.com

www.go-faster.co.uk

Another book – also recommended by Cary Millsap

• The Goal: A Process of Ongoing Improvement • Eliyahu Goldratt, Jeff Cox www.go-faster.co.uk

Aphorism

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

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

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) www.go-faster.co.uk

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 – Metalink note 39817.1

details structure of trace files • Usually process it with

tkprof

www.go-faster.co.uk

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 and when I should trace it.

www.go-faster.co.uk

Initialisation parameters

• • • • • timed_statistics = TRUE user_dump_dest = '' max_dump_file_size = _trace_files_public = TRUE trace_file_identifier = '' www.go-faster.co.uk

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 –

Recommend always set it true

www.go-faster.co.uk

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

_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

tracefile_identifier =

• 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

tracefile_identifier =

ALTER SESSION SET TRACE_FILE_IDENTIFIER = ‘nVision_Report_NVSRUN_159’; /u01/app/oracle/admin/F84SP1/udump/ f84sp1_ora_41776_nVision_Report_NVSRUN_159 .trc

www.go-faster.co.uk

How to enable SQL trace

• From UKOUG2002 – Advanced Oracle Diagnostics • Julian Dyke – www.juliandyke.com

– 10 methods of enabling trace information in Oracle www.go-faster.co.uk

How to enable SQL trace

ALTER SESSION SET EVENTS '10046 trace name context forever, level '

Level 0 1 4 8 12 Description Disabled Same as ALTER SESSION SET SQL_TRACE=TRUE Include bind variable information Include wait statistics Include bind variable and wait statistics

www.go-faster.co.uk

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

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

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

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

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

How to enable SQL trace

• In another session ( DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION

SI NUMBER, SE NUMBER, -- SID -- Serial Number SQL_TRACE BOOLEAN -- TRUE to enable; -- FALSE to disable ); • SID and SERIAL# from V$SESSION.

www.go-faster.co.uk

How to enable SQL trace

• In another session ( DBMS_SUPPORT.START_TRACE_IN_SESSION

SI NUMBER, SE NUMBER, -- SID -- Serial Number (can be 0) WAITS BOOLEAN, -- Include waits (default FALSE) BINDS BOOLEAN -- Include binds (default FALSE) ); www.go-faster.co.uk

How to disable SQL trace

• In another session ( DBMS_SUPPORT.STOP_TRACE_IN_SESSION

SI NUMBER, SE NUMBER, -- SID -- Serial Number (can be 0) ); www.go-faster.co.uk

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

New in Oracle 10g

• In another session ( DBMS_MONITOR.SESSION_TRACE_ENABLE

SI NUMBER, SE NUMBER, -- SID -- Serial Number (can be 0) WAITS BOOLEAN, -- Include waits (default FALSE) BINDS BOOLEAN -- Include binds (default FALSE) ); www.go-faster.co.uk

New in Oracle 10g

• In another session ( DBMS_MONITOR.SESSION_TRACE_DISABLE

SI NUMBER, SE NUMBER, -- SID -- Serial Number (can be 0) ); www.go-faster.co.uk

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

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('200503111800','YYYYMMDDHH24MI')) www.go-faster.co.uk

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 = '''|| END; TRANSLATE(:new.prcstype||'_'||:new.prcsname,' -','__')||'_'|| :new.prcsinstance||''''; EXECUTE IMMEDIATE 'ALTER SESSION SET EVENTS ''10046 trace name context forever, level 8'''; / www.go-faster.co.uk

What is in the SQL trace file

• See Metalink Note 39817.1

for details of trace file structure www.go-faster.co.uk

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

SQL trace file sections

• With event 10046 – Binds • (level 4) – Waits • (level 8) • Timings – – centisecond timings (Oracle 7 & 8) microsecond from Oracle 9 www.go-faster.co.uk

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

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

• Oracle supplied utility – – – Transient Kernel Profiler 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

tkprof

tkprof sample

SELECT VERSION FROM PSVERSION WHERE OBJECTTYPENAME = 'SYS' call count cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 0.00 0.00 0 2 0 1 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 3 0.00 0.00 0 2 0 1 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 24 Rows Row Source Operation ------ -------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID PSVERSION 1 INDEX UNIQUE SCAN PS_PSVERSION (object id 31454) www.go-faster.co.uk

Row source statistics

• From Oracle 9.2.0.2 ALTER SESSION SET STATISTICS_LEVEL = ALL; – Added to SQL Trace stat line – Appears in tkprof output – Performance overhead www.go-faster.co.uk

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 count cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 1 0.02 0.17 0 0 0 0 Execute 116759 20.76 40.24 0 0 0 0 Fetch 116759 25.60 88.40 1910 440408 0 89622 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 233519 46.38 128.81 1910 440408 0 89622 www.go-faster.co.uk

Row source statistics

Rows Row Source Operation ------ -------------------------------------------------- 89622 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

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= www.go-faster.co.uk

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

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

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 www.go-faster.co.uk

Execution plan (from stat lines)

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 'PS#ITEM' (NON-UNIQUE) 8 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' 16 INDEX (RANGE SCAN) OF (object id 4854) 0 SORT (AGGREGATE) 0 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' 0 INDEX (RANGE SCAN) OF (object id 4854) www.go-faster.co.uk

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) 1000040 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUSTOMER' 1000400 INDEX (RANGE SCAN) OF 'PS#CUSTOMER' (NON-UNIQUE) 1000048 INDEX (RANGE SCAN) OF 'PS#ITEM' (NON-UNIQUE) 8 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' 16 INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE) 0 SORT (AGGREGATE) 0 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' 0 INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE) www.go-faster.co.uk

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 AND AND AND P.PROCESS_INSTANCE = 212 S.RECNAME = 'CUSTOMER' S.SETID = C.SETID S.SETCNTRLVALUE = I.BUSINESS_UNIT AND AND AND AND AND I.CUST_ID = C.CUST_ID I.ITEM_STATUS = 'O' O.SETID = C.REMIT_FROM_SETID O.CUST_ID = C.REMIT_FROM_CUST_ID O.EFFDT = ( SELECT FROM MAX(Z.EFFDT) PS_CUST_OPTION Z WHERE AND AND AND AND O.PP_METHOD <> ' ' Z.SETID = O.SETID Z.CUST_ID = O.CUST_ID Z.EFF_STATUS = 'A' Z.EFFDT <= P.PAYMENT_DT) 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

PP_METHOD <> ' '

2. Start to draw the query

EFFDT

PS_CUST_OPTION (O)

RECNAME = 'CUSTOMER' O.SETID = C.REMIT_FROM_SETID O.CUST_ID = C.REMIT_FROM_CUST_ID SETID

PS_CUSTOMER (C)

CUST_ID

PS_SET_CNTRL_REC (S)

REF_QUALIFIER_CODE = 'I' S.SETCNTRLVALUE = I.BUSINESS_UNIT

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

www.go-faster.co.uk

PS_PP_PAYMENT_TMP (P)

54 PROCESS_INSTANCE = 212

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 'PS#CUSTOMER' (NON-UNIQUE) 1000048 (5) INDEX (RANGE SCAN) OF 'PS#ITEM' (NON-UNIQUE) 8 (6) TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' 16 INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE) 0 SORT (AGGREGATE) 0 TABLE ACCESS (BY INDEX ROWID) OF 'PS_CUST_OPTION' INDEX (RANGE SCAN) OF 'PS_CUST_OPTION' (UNIQUE) www.go-faster.co.uk

5. Put the order in the diagram

PP_METHOD <> ' ' EFFDT RECNAME = 'CUSTOMER' O.SETID = C.REMIT_FROM_SETID O.CUST_ID = C.REMIT_FROM_CUST_ID SETID S.SETCNTRLVALUE = I.BUSINESS_UNIT

CUST_ID REF_QUALIFIER_CODE = 'I' X.REF_VALUE = I.ITEM

I.ITEM_STATUS = 'O' P.DEPOSIT_BU = X.DEPOSIT_BU P.DEPOSIT_ID = X.DEPOSIT_ID

P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM

www.go-faster.co.uk

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 STORAGE (INITIAL 10K NEXT 98K MAXEXTENTS 110 PCTINCREASE 0) / www.go-faster.co.uk

PP_METHOD <> ' ' RECNAME = 'CUSTOMER' EFFDT

New Execution Order

O.SETID = C.REMIT_FROM_SETID O.CUST_ID = C.REMIT_FROM_CUST_ID SETID S.SETCNTRLVALUE = I.BUSINESS_UNIT

CUST_ID REF_QUALIFIER_CODE = 'I' X.REF_VALUE = I.ITEM

I.ITEM_STATUS = 'O' P.DEPOSIT_BU = X.DEPOSIT_BU P.DEPOSIT_ID = X.DEPOSIT_ID

P.PAYMENT_SEQ_NUM = X.PAYMENT_SEQ_NUM

www.go-faster.co.uk

58 PROCESS_INSTANCE = 212

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 www.go-faster.co.uk

Example 2: Wait Events

• • How do you know it’s not the database?

Event 10046,8 – enable wait information.

www.go-faster.co.uk

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 cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 1 0.00 0.00 0 0 0 0 Execute 22510 73.30 1269.24 31542 45040 503607 558966 Fetch 0 0.00 0.00 0 0 0 0 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 22511 73.30 1269.24 31542 45040 503607 558966 www.go-faster.co.uk

Wait events report discrepancy

Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------- Waited --------- ----------- SQL*Net more data from client 27495 0.56 1036.26

db file sequential read 31542 0.97 148.99

SQL*Net message from client 22510 0.44 80.41

free buffer waits 19 1.02 4.74

SQL*Net message to client 22510 0.01 0.08

latch free 5 0.02 0.08

buffer busy waits 1 0.00 0.00

log file switch completion 1 0.06 0.06

www.go-faster.co.uk

After resolving network problem

call count cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 1 0.00 0.00 0 0 0 0 Execute 22264 103.07 113.04 2521 86624 553966 662676 Fetch 0 0.00 0.00 0 0 0 0 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 22265 103.07 113.04 2521 86624 553966 662676 Event waited on Times Max. Wait Total Waited ---------------------------- Waited --------- ----------- SQL*Net message from client 22264 0.47 88.84

SQL*Net more data from client 29138 0.47 6.69

www.go-faster.co.uk

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 cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 5858 0.57 0.51 0 0 0 0 Execute 27973 7.60 1989.00 1630 95825 662 645 Fetch 0 0.00 0.00 0 0 0 0 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 33831 8.17 1989.52 1630 95825 662 645 www.go-faster.co.uk

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

www.go-faster.co.uk

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

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

Summary at bottom of report

• Active process making lots of calls to the database OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 12197 3.85 4.50 621 25979 0 0 Execute 870343 537.36 750.89 70625 18372702 2047141 2657717 Fetch 710951 405.99 917.94 229999 10341004 73 3030039 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 1593491 947.20 1673.34 301245 28739685 2047214 5687756 www.go-faster.co.uk

Is it the database?

Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------- Waited --------- ----------- SQL*Net message to client 881285 0.01 1.68

SQL*Net message from client 881285 1.22 2491.24

log file sync 185 1.01 28.18

SQL*Net more data from client 62845 0.40 5.27

SQL*Net more data to client 21008 0.00 1.54

db file sequential read 201760 2.39 451.60

direct path write 2632 0.67 49.76

direct path read 4034 0.71 28.97

www.go-faster.co.uk

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?) 4790 2491 1673 626 www.go-faster.co.uk

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 www.go-faster.co.uk

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 cpu elapsed disk query current rows ------- ----- -------- ---------- ---------- ---------- --------- --------- Parse 1 0.00 0.00 0 0 0 0 Execute 5598 1.06 1.07 0 0 0 0 Fetch 5598 4411.76 4644.73 127 183871489 0 1117812 ------- ----- -------- ---------- ---------- ---------- --------- --------- total 11197 4412.82 4645.80 127 183871489 0 1117812 www.go-faster.co.uk

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

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

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 www.go-faster.co.uk

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 P2.EMPLID=RA.EMPLID

AND S.EMPL_RCD=RA.EMPL_RCD

AND P2.EMPL_RCD=RA.EMPL_RCD

AND S.GP_PAYGROUP=RA.GP_PAYGROUP

AND P2.GP_PAYGROUP=RA.GP_PAYGROUP

AND S.CAL_ID=RA.CAL_ID

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'; www.go-faster.co.uk

A three table join

RUN_CNTL_ID=:1 OPRID=:2 :3 <= `EMPLID <= :4 PRD_TYPE='R' S.PRIOR_VER_NUM=P2.RSLT_VER_NUM

S.PRIOR_REV_NUM=P2.RSLT_REV_NUM

PS_GP_PYE_STAT_WRK (S) 1

EMPLID, EMPL_RCD, GP_PAYGROUP, CAL_ID, RSLT_SEG_NUM

PS_GP_PYE_PRC_STAT (P2) 3

EMPLID, EMPL_RCD, GP_PAYGROUP, CAL_RUN_ID, ORIG_CAL_RUN_ID, CAL_ID, RSLT_SEG_NUM

PS_GP_RSLT_ACUM (RA) 2

www.go-faster.co.uk

ACM_PRD_OPTN='1' 77

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) ...

www.go-faster.co.uk

Explicitly add implicit joins

AND P2.EMPLID=S.EMPLID AND P2.EMPL_RCD=S.EMPL_RCD AND P2.GP_PAYGROUP=S.GP_PAYGROUP AND P2.CAL_ID=S.CAL_ID

www.go-faster.co.uk

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 S.PRIOR_VER_NUM=P2.RSLT_VER_NUM

S.PRIOR_REV_NUM=P2.RSLT_REV_NUM

EMPLID, EMPL_RCD, GP_PAYGROUP, CAL_ID, RSLT_SEG_NUM

PS_GP_PYE_PRC_STAT (P2) 2

EMPLID, EMPL_RCD, GP_PAYGROUP, CAL_RUN_ID, ORIG_CAL_RUN_ID, CAL_ID, RSLT_SEG_NUM

PS_GP_RSLT_ACUM (RA) 3

www.go-faster.co.uk

ACM_PRD_OPTN='1' 80

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) ...

www.go-faster.co.uk

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?

www.go-faster.co.uk

Questions?

www.go-faster.co.uk