Tracing a Specific SQL Statement
from http://www.dbaref.com/tracing-performance-issues-in-oracle/tracingaspecificsqlstatement
You want to trace a specific SQL statement to find where the database is spending its time during the execution of the statement.
|
1. Setup the trace
SQL> alter session set events 'sql_trace level 12'; Session altered. =============================================================================================== You can also choose to trace specific SQL statement by specifying the SQL ID. SQL> select sql_text,sql_id from v$sql where sql_text ='select count(*) from dict'; SQL_TEXT -------------------------------------------------------------------------------- SQL_ID ------------- select count(*) from dict 7ugyh72gqtm58 SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58] level 12'; You can also trace multiple SQL statement SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58|7ugyh72gqtm59|7ugyh72gqtm60] level 12'; You can trace a specific SQL statement running on a different session by issuing an alter system set events command. SQL> alter system set events 'sql_trace [sql:7ugyh72gqtm58] level 12'; =============================================================================================== 2. EXECUTE the SQL Statement SQL> select count(*) from dict; COUNT(*) ---------- 2553 3. Set tracing OFF SQL> alter session set events 'sql_trace off'; Session altered. =============================================================================================== SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58] off'; SQL> alter session set events 'sql_trace [sql:7ugyh72gqtm58|7ugyh72gqtm59|7ugyh72gqtm60] off'; SQL> alter system set events 'sql_trace [sql:7ugyh72gqtm58] off'; =============================================================================================== 4. Finding the trace file [oracle@usha ~]$ adrci ADRCI: Release 11.2.0.1.0 - Production on Sun Apr 22 10:07:58 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. ADR base = "/u01/app/oracle" adrci> show tracefile -t 22-APR-12 08:44:35 diag/rdbms/testdb/testdb/trace/testdb_vktm_19533.trc 22-APR-12 08:44:43 diag/rdbms/testdb/testdb/trace/testdb_p000_19573.trc 22-APR-12 08:44:43 diag/rdbms/testdb/testdb/trace/testdb_p001_19575.trc 22-APR-12 08:44:46 diag/rdbms/testdb/testdb/trace/testdb_dbrm_19541.trc 22-APR-12 08:45:04 diag/rdbms/testdb/testdb/trace/testdb_mmon_19559.trc 22-APR-12 08:45:15 diag/rdbms/testdb/testdb/trace/testdb_j007_19615.trc 22-APR-12 08:46:13 diag/rdbms/testdb/testdb/trace/testdb_j000_19623.trc 22-APR-12 08:49:51 diag/rdbms/testdb/testdb/trace/alert_testdb.log 22-APR-12 09:05:34 diag/rdbms/testdb/testdb/trace/testdb_ora_19571.trc adrci> =========================================================================================== NOTE: Issue the following statement to set an identifier for your trace file. SQL> alter session set events 'sql_trace level 12'; Session altered. SQL> alter session set tracefile_identifier='MyTune1'; Session altered. SQL> select count(*) from dict; COUNT(*) ---------- 2553 SQL> alter session set events 'sql_trace off'; Session altered. SQL> quit Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production With the Partitioning, OLAP, Data Mining and Real Application Testing options [oracle@usha ~]$ adrci ADRCI: Release 11.2.0.1.0 - Production on Sun Apr 22 10:21:03 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. ADR base = "/u01/app/oracle" adrci> show tracefile -t 22-APR-12 08:45:15 diag/rdbms/testdb/testdb/trace/testdb_j007_19615.trc 22-APR-12 08:46:13 diag/rdbms/testdb/testdb/trace/testdb_j000_19623.trc 22-APR-12 09:05:34 diag/rdbms/testdb/testdb/trace/testdb_ora_19571.trc 22-APR-12 09:15:46 diag/rdbms/testdb/testdb/trace/alert_testdb.log 22-APR-12 09:20:10 diag/rdbms/testdb/testdb/trace/testdb_ora_19868.trc 22-APR-12 09:20:57 diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc adrci> SQL>alter session set tracefile_identifier='MyTune1'; 5. Examining the RAW SQL Trace File Open the file in a text editor. Here are few things you will see [oracle@usha ~]$ vi /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc *** 2012-04-22 10:20:57.614 WAIT #7: nam='SQL*Net message from client' ela= 24056253 driver id=1650815232 #bytes=1 p3=0 obj#=68 tim=1335104457614532 CLOSE #7:c=0,e=42,dep=0,type=0,tim=1335104457614724 ===================== PARSING IN CURSOR #4 len=40 dep=0 uid=0 oct=42 lid=0 tim=1335104457614858 hv=103992512 ad='0' sqlid='7226hs0335m60' alter session set events 'sql_trace off' END OF STMT PARSE #4:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1335104457614856 EXEC #4:c=0,e=262,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1335104457615189 ~ 6. Formatting the TRACE Files using TKPROF [oracle@usha ~]$ tkprof /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc mytune1.prf TKPROF: Release 11.2.0.1.0 - Development on Sun Apr 22 10:27:15 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. [oracle@usha ~]$ ls mytune1.prf mytune1.prf [oracle@usha ~]$ vi mytune1.prf [oracle@usha ~]$ 7. Analyze the TKPROF Output Header TKPROF: Release 11.2.0.1.0 - Development on Sun Apr 22 10:27:15 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. Trace file: /u01/app/oracle/diag/rdbms/testdb/testdb/trace/testdb_ora_19868_MyTune1.trc Sort options: default ******************************************************************************** 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 ******************************************************************************** EXECUTION STATISTICS SQL ID: 7ugyh72gqtm58 Plan Hash: 2690817011 select count(*) from dict call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.02 0.04 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.12 0.76 542 2019 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.14 0.81 542 2019 0 1 Misses in library cache during parse: 1 ================================================================================================ count -> The no of times the database parsed,executed or fetched this statement. cpu -> CPU time used for the parse/execute/fetch phases elapsed ->Total elapsed time in SECONDS for the parse/execute/fetch phases disk -> No of physical block reads for the parse/execute/fetch phases query -> No of data blocks read with logical reads from the buffer cache in consistent mode for the parse/execute/fetch phases (for a select statement) current -> No of data blocks read and retrieved with logical reads from the buffer cache in current mode ( for insert, update, delete, and merge statements) rows -> No of fetched rows for a select statement or the no of rows inserted, deleted or updated respectively for an insert, update, delete, and merge statements. ================================================================================================ Row Source Operation Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Rows Row Source Operation ------- --------------------------------------------------- 1 SORT AGGREGATE (cr=2019 pr=542 pw=315 time=0 us) 2553 VIEW DICTIONARY (cr=2019 pr=542 pw=315 time=39938 us cost=514 size=0 card=2140) 2553 UNION-ALL (cr=2019 pr=542 pw=315 time=34069 us) 1415 CONCATENATION (cr=226 pr=64 pw=0 time=15907 us) 698 FILTER (cr=78 pr=64 pw=0 time=8131 us) 698 FILTER (cr=78 pr=64 pw=0 time=6737 us) 5177 HASH JOIN OUTER (cr=78 pr=64 pw=0 time=8963 us cost=24 size=1845 card=41) 726 INDEX RANGE SCAN I_OBJ2 (cr=10 pr=0 pw=0 time=1329 us cost=10 size=1591 card=43)(object id 37) 15871 INDEX FAST FULL SCAN I_COM1 (cr=68 pr=64 pw=0 time=18813 us cost=13 size=94328 card=11791)(object id 138) 1 FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1) 372 FILTER (cr=74 pr=0 pw=0 time=2968 us) 3030 HASH JOIN OUTER (cr=74 pr=0 pw=0 time=4164 us cost=20 size=720 card=16) 385 INDEX RANGE SCAN I_OBJ2 (cr=6 pr=0 pw=0 time=576 us cost=6 size=629 card=17)(object id 37) 1 FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1) 15871 INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=18429 us cost=13 size=94328 card=11791)(object id 138) 345 FILTER (cr=74 pr=0 pw=0 time=3554 us) 3327 HASH JOIN OUTER (cr=74 pr=0 pw=0 time=8954 us cost=20 size=1080 card=24) 360 INDEX RANGE SCAN I_OBJ2 (cr=6 pr=0 pw=0 time=837 us cost=6 size=925 card=25)(object id 37) 1 FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1) 15871 INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=17917 us cost=13 size=94328 card=11791)(object id 138) 21 FILTER (cr=112 pr=0 pw=0 time=80 us) 99 HASH JOIN OUTER (cr=112 pr=0 pw=0 time=196 us cost=36 size=574 card=14) 21 INLIST ITERATOR (cr=44 pr=0 pw=0 time=820 us) 21 INDEX RANGE SCAN I_OBJ2 (cr=44 pr=0 pw=0 time=0 us cost=22 size=462 card=14)(object id 37) 15871 INDEX FAST FULL SCAN I_COM1 (cr=68 pr=0 pw=0 time=17917 us cost=13 size=94328 card=11791)(object id 138) 1117 FILTER (cr=1681 pr=478 pw=315 time=68820 us) 1117 HASH JOIN (cr=1681 pr=478 pw=315 time=65968 us cost=416 size=2390955 card=16265) 27702 INDEX FAST FULL SCAN I_OBJ2 (cr=758 pr=0 pw=0 time=43402 us cost=204 size=408776 card=11048)(object id 37) 2715 HASH JOIN (cr=923 pr=163 pw=240 time=4911 us cost=211 size=1789920 card=16272) 3751 INDEX FAST FULL SCAN I_OBJ2 (cr=758 pr=0 pw=0 time=12250 us cost=204 size=178533 card=2151)(object id 37) 23789 TABLE ACCESS FULL SYN$ (cr=165 pr=163 pw=0 time=27880 us cost=6 size=642303 card=23789) 0 NESTED LOOPS (cr=0 pr=0 pw=0 time=0 us cost=2 size=21 card=1) 0 INDEX RANGE SCAN I_OBJAUTH1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=8 card=1)(object id 62) 0 FIXED TABLE FULL X$KZSRO (cr=0 pr=0 pw=0 time=0 us cost=0 size=13 card=1) 0 FIXED TABLE FULL X$KZSPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=26 card=1) ================================================================================================ cr -> Blocks retrieved through a logical read in the consistent mode pr -> no of blocks read through a physical disk read pw -> No of blocks written with a physical write to a disk time -> Total time in milliseconds spent processing the operation cost ->Estimated cost of the operation size -> Estimated amount of data (bytes) returned by the operation. card -> Estimated no of rows returned by the operation ================================================================================================ WAIT EVENTS Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 2 0.00 0.00 db file sequential read 2 0.01 0.03 db file scattered read 8 0.01 0.08 Disk file operations I/O 1 0.01 0.01 direct path write temp 21 0.03 0.25 asynch descriptor resize 4 0.00 0.00 direct path read 19 0.03 0.22 direct path read temp 21 0.00 0.00 SQL*Net message from client 2 24.05 24.05 ******************************************************************************** |
|
小小菜鸟一枚
