10046 Getting Started: Use 10046 to view the execution plan and read the trace file, 10046 trace

10046 Getting Started: Use 10046 to view the execution plan and read the trace file, 10046 trace

**************************************** * ********************* 1. enable 10046 ************************************** * ********************* SQL> oradebug setmypid Statement processed. // activate the 10046 event SQL> oradebug event 10046 trace name context forever, level 12; Statement processed. SQL> select count (*) from scott. tblorders; COUNT (*) ---------- 167 // close the 10046 event SQL> oradebug event 10046 trace name context off; Statement processed in the current session. // use oradebug tracefile_name to directly view the location of the generated trace file SQL> oradebug tracefile_name; /u01/app/oracle/diag/rdbms/orcl/trace/orcl_ora_2551.trc ********************** * ************************************* 2. directly read the file ************************************* * ********************** -------------------- trace file content Trace file/u01/app/oracle/diag/rdbms /orcl/trace/orcl_ora_2551.trcOracle Database 11g Enterprise Edition Release 11.2.0.4.0-64bit ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing optionsORACLE_HOME =/u01/app/oracle/product/11.2.0/db_1System name: LinuxNode name: timesten. ocp. comRelease: 2.6.32-431. el6.x86 _ 64 Version: #1 SMP Fri Nov 22 03:15:09 UTC 2013 Machine: x86_64Instance name: orclRedo thread mounted by this instance: 1 Oracle process number: 20 Unix process pid: 2551, image: oracle@timesten.ocp.com (TNS V1-V3) *** 17:34:40. 127 *** session id: (132.9911) 17:34:40. 127 *** client id :() 17:34:40. 127 *** service name :( SYS $ USERS) 17:34:40. 127 *** module name :( sqlplus@timesten.ocp.com (TNS V1-V3) 17:34:40. 127 *** action name :() 17:34:40. 127 Processing Oradebug command 'setmypid '*** 17:34:40. 127 Oradebug command 'setmypid 'console output: <none> *** 17:34:48. 483 Processing Oradebug command 'event 10046 trace name context forever, level 12' *** 17:34:48. 484 Oradebug command 'event 10046 trace name context forever, level 12' console output: <none> WAIT #0: nam = 'SQL * Net message to client' ela = 2 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560888484461 *** 17:35:09. 044 WAIT #0: nam = 'SQL * Net message from client' ela = 20559954 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560909044435 ======== ============== parsing in cursor #140199425457600 len = 37 dep = 0 uid = 0 oct = 3 lid = 0 tim = 1423560909045924 hv = 2120411436 ad = '28d609c60' sqlid = '23uhtxpz65u9c' select count (*) from scott. tblordersEND of stmtparse #140199425457600: c = 1000, e = 1393, p = 0, cr = 0, cu = 0, mis = 1, r = 0, dep = 0, og = 1, plh = 1853518045, tim = 1423560909045922 EXEC #140199425457600: c = 0, e = 54, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 1, plh = 1853518045, tim = 1423560909046084 WAIT #140199425457600: nam = 'SQL * Net message to client' ela = 2 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560909046130 FETCH #140199425457600: c = 0, e = 99,p = 0, cr = 1, cu = 0, mis = 0, r = 1, dep = 0, og = 1, plh = 1853518045, tim = 1423560909046258 STAT #140199425457600 id = 1 cnt = 1 pid = 0 pos = 1 obj = 0 op = 'sort AGGREGATE (cr = 1 pr = 0 pw = 0 time = 110 us) 'stat #140199425457600 id = 2 cnt = 167 pid = 1 pos = 1 obj = 89045 op = 'index full scan PK_ORDERID (cr = 1 pr = 0 pw = 0 time = 76 us cost = 1 size = 0 card = 167) 'Wait #140199425457600: nam = 'SQL * Net message from client' ela = 148 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560909046527 FETCH #140199425457600: c = 0, e = 1, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 0, PL = 1853518045, tim = 1423560909046560 WAIT #140199425457600: nam = 'SQL * Net message to client' ela = 1 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560909046581 *** 17:35:27. 589 WAIT #140199425457600: nam = 'SQL * Net message from client' ela = 18543034 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560927589630 CLOSE #140199425457600: c = 0, e = 10, dep = 0, type = 0, tim = 1423560927589767 *** 17:35:27. 589 Processing Oradebug command 'event 10046 trace name context off' *** 17:35:27. 590 Oradebug command 'event 10046 trace name context off' console output: <none> *** 17:35:35. 918 Processing Oradebug command 'tracefile _ name' *** 17:35:35. 918 Oradebug command 'tracefile _ name' console output: /u01/app/oracle/diag/rdbms/orcl/trace/orcl_ora_2551.trc ********************** ********************************** ********************* Part 1: parse (resolution) parsing in cursor #140199425457600 len = 37 dep = 0 uid = 0 oct = 3 lid = 0 tim = 1423560909045924 hv = 2120411436 ad = '28d60960' sqlid = '23uhtxpz65u9c' cursor number lensql statement length depsql statement recursion depth uiduser id octoracle command type extends privilege user id timtimestamp, timestamp hvhash id adsql address, used in v $ sqltext sqlid SQL id Part 1: exec (executed) PARSE # 2nd: c = 140199425457600, e = 1000, p = 0, cr = 0, cu = 0, mis = 1, r = 0, dep = 0, og = 1, plh = 1853518045, tim = 1423560909045922 EXEC #140199425457600: c = 0, e = 54, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 1, PL = 1853518045, tim = 1423560909046084c CPU consumed time e Elapsed time p number of physical reads cr number of buffers retrieved for CR reads logical read data block cu number of buffers retrieved in current mode (data blocks read in current mode) mis cursor missed in the cache library cache lost cursor, hard resolution times r number of rows processed by rows processed dep recursive depth og optimizer mode [1: all_rows, 2: first_rows, 3: rule, 4: choose] plh plan hash value tim timestamp Part 1: WAIT events occurring during execution WAIT #0: nam = 'SQL * Net message from client'ela = 20559954 driver id = 1650815232 # bytes = 1 p3 = 0 obj #=-1 tim = 1423560909044435nam an event that we waited for waiting for an event ela time consumed by this operation p3 block number trm timestamp Part 1: execution Plan STAT #140199425457600 id = 1 cnt = 1 pid = 0 pos = 1 obj = 0 op = 'sort AGGREGATE (cr = 1 pr = 0 pw = 0 time = 110 us) 'stat #140199425457600 id = 2 cnt = 167 pid = 1 pos = 1 obj = 89045 op = 'index full scan PK_ORDERID (cr = 1 pr = 0 pw = 0 time = 76 us cost = 1 size = 0 card = 167) 'cnt current row source returned number of rows pid parent id of this row source current row source parent node id pos position in explain plan execution plan position obj object id of row source (if this is a base object) op the row source access operation ********************************** **************************************** **************************************** **************************************** **************************************** * **************************** 3. use the tkprof command to translate the trace file ********************************** * ************************ tkprof/u01/app/oracle/diag/rdbms/orcl /orcl/trace/orcl_ora_2551.trc. /test. trcTKPROF: Release 11.2.0.4.0-Development on Tuesday February 10 17:47:28 2015 Copyright (c) 1982,201 1, Oracle and/or its affiliates. all rights reserved. trace file:/u01/app/oracle/diag/rdbms/orcl/trace/orcl_ora_2551.trcSort options: default *************************************** **************************************** * count = number of times OCI procedure was executedcpu = cpu time in seconds executing elapsed = elapsed time in seconds executingdisk = number of physical reads of buffers from diskquery = number of buffers gotten for consistent readcurrent = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call **************************** **************************************** * *********** SQL ID: 23uhtxpz65u9c Plan Hash: 1853518045 select count (*) from scott. tblorderscall count cpu elapsed disk query current rows ------- ------ -------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0 0 0 0 Fetch 2 0.00 0 0 1 ------- ------ -------- ---------- total 4 0.00 0.00 0 1 0 1 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWSParsing user id: SYSNumber of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) row Source Operation ---------- --------------------------------------------------- 1 1 1 sort aggregate (cr = 1 pr = 0 pw = 0 time = 110 us) 167 167 index full scan PK_ORDERID (cr = 1 pr = 0 pw = 0 time = 76 us cost = 1 size = 0 card = 167) (object id 167) 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 SQL * Net message from client 2 18.54 18.54 *************** **************************************** * ********************** overall totals for all NON-RECURSIVE STATEMENTScall count cpu elapsed disk query current rows ------------- -------- ---------- Parse 1 0.00 0.00 0 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 0 Fetch 2 0.00 0.00 0 0 1 ------- ------ -------- ------------ total 4 0.00 0.00 0 1 0 1 Misses in library cache during parse: 1 Elapsed times include waiting on following events: Event waited on Times Max. wait Total Waited expired Waited ---------- SQL * Net message to client 3 0.00 0.00 SQL * Net message from client 3 20.55 39.10 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall count cpu elapsed disk query current rows ------------- -------- ---------- Parse 0 0.00 0.00 0.00 0 0 0 0 Execute 0 0.00 0.00 0 0 0 0 0 Fetch 0 0.00 0 0 0 0 ------- ------ -------- ---------- ------------ total 0 0 0.00 0.00 0 0 0 0 Misses in library cache during parse: 0 1 user SQL statements in session. 0 internal SQL statements in session. 1 SQL statements in session. **************************************** **************************************** trace file: /u01/app/oracle/diag/rdbms/orcl/trace/orcl_ora_2551.trcTrace file compatibility: 11.1.0.7Sort options: default 1 session in tracefile. 1 user SQL statements in trace file. 0 internal SQL statements in trace file. 1 SQL statements in trace file. 1 unique SQL statements in trace file. 66 lines in trace file. 0 elapsed seconds in trace file.