1 / 51

Tuning with Oracle’s SQL Trace

Tuning with Oracle’s SQL Trace. David Kurtz Go-Faster Consultancy Ltd. david@go-faster.co.uk www.go-faster.co.uk. 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.

tamika
Download Presentation

Tuning with Oracle’s SQL Trace

An Image/Link below is provided (as is) to download presentation Download Policy: Content on the Website is provided to you AS IS for your information and personal use and may not be sold / licensed / shared on other websites without getting consent from its author. Content is provided to you AS IS for your information and personal use only. Download presentation by click this link. While downloading, if for some reason you are not able to download a presentation, the publisher may have deleted the file from their server. During download, if you can't get a presentation, the file might be deleted by the publisher.

E N D

Presentation Transcript

  1. Tuning with Oracle’s SQL Trace David Kurtz Go-Faster Consultancy Ltd. david@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 Oracle’s 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 can’t 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 <sql statement> • PLAN_TABLE • set autotrace on

  13. select /*+RULE*/ * from dual; Execution Plan --------------------------- 0 SELECT STATEMENT Optimizer=HINT: RULE 1 0 TABLE ACCESS (FULL) OF 'DUAL' select /*+ALL_ROWS*/ * from dual; Execution Plan --------------------------- 0 SELECT STATEMENT Optimizer=HINT: ALL_ROWS (Cost=1 Card=1 Bytes=2) 1 0 TABLE ACCESS (FULL) OF 'DUAL' (Cost=1 Card=1 Bytes=2) Rule -v- Cost Based Optimiser

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

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

  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_STATISTICS=TRUE • Ad-hoc • ALTER SYSTEM SET TIMED_STATISTICS=TRUE; • Small performance overhead

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

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

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

  21. 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 ’ ...

  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= ] 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 ...

  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 <= 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

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

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

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

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

  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. 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? Theory & Practice

  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 SQL*Plus • 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 SQL*Plus

  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_TRACE=TRUE 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 <= 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','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; /

  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','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; /

  49. Tuning with Oracle’s SQL Trace • Tuning • SQL Trace • TKPROF • Explain Plan • Graphical Technique • Techniques for enabling SQL Trace

  50. Any Questions?

More Related