10046入門:使用 10046 查看執行計畫並讀懂 trace檔案，10046trace

10046入門:使用 10046 查看執行計畫並讀懂 trace檔案，10046trace

*************************************************************1.開啟10046*************************************************************SQL> oradebug setmypid  Statement processed.    // 啟用 10046 事件  SQL> oradebug event 10046 trace name context forever,level 12;  Statement processed.    SQL> select count(*) from scott.tblorders;  COUNT(*)----------       167  // 在當前 session 關閉 10046 事件  SQL> oradebug event 10046 trace name context off;  Statement processed.    // 使用 oradebug tracefile_name 可以直接看到產生的 trace 檔案的位置  SQL> oradebug tracefile_name;  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc*************************************************************2.直接讀取檔案*************************************************************----------------------trace檔案內容Trace file /u01/app/oracle/diag/rdbms/orcl/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_64Version:#1 SMP Fri Nov 22 03:15:09 UTC 2013Machine:x86_64Instance name: orclRedo thread mounted by this instance: 1Oracle process number: 20Unix process pid: 2551, image: oracle@timesten.ocp.com (TNS V1-V3)*** 2015-02-10 17:34:40.127*** SESSION ID:(132.9911) 2015-02-10 17:34:40.127*** CLIENT ID:() 2015-02-10 17:34:40.127*** SERVICE NAME:(SYS$USERS) 2015-02-10 17:34:40.127*** MODULE NAME:(sqlplus@timesten.ocp.com (TNS V1-V3)) 2015-02-10 17:34:40.127*** ACTION NAME:() 2015-02-10 17:34:40.127 Processing Oradebug command 'setmypid'*** 2015-02-10 17:34:40.127Oradebug command 'setmypid' console output: <none>*** 2015-02-10 17:34:48.483Processing Oradebug command 'event 10046 trace name context forever,level 12'*** 2015-02-10 17:34:48.484Oradebug 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*** 2015-02-10 17:35:09.044WAIT #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=1423560909045922EXEC #140199425457600:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1853518045,tim=1423560909046084WAIT #140199425457600: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909046130FETCH #140199425457600:c=0,e=99,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=1853518045,tim=1423560909046258STAT #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=1423560909046527FETCH #140199425457600:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1853518045,tim=1423560909046560WAIT #140199425457600: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560909046581*** 2015-02-10 17:35:27.589WAIT #140199425457600: nam='SQL*Net message from client' ela= 18543034 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1423560927589630CLOSE #140199425457600:c=0,e=10,dep=0,type=0,tim=1423560927589767*** 2015-02-10 17:35:27.589Processing Oradebug command 'event 10046 trace name context off'*** 2015-02-10 17:35:27.590Oradebug command 'event 10046 trace name context off' console output: <none>*** 2015-02-10 17:35:35.918Processing Oradebug command 'tracefile_name'*** 2015-02-10 17:35:35.918Oradebug command 'tracefile_name' console output: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc***************************解釋******************************************************第1部分:parse(解析) PARSING IN CURSOR #140199425457600 len=37 dep=0 uid=0 oct=3 lid=0 tim=1423560909045924 hv=2120411436 ad='28d609c60' sqlid='23uhtxpz65u9c'cursor cursor number lensql 語句長度 depsql 語句遞迴深度 uiduser id octoracle command type lidprivilege user id timtimestamp，時間戳記 hvhash id adsql address 地址, 用在 v$sqltext sqlid sql id第2部分:exec(執行)PARSE #140199425457600:c=1000,e=1393,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1853518045,tim=1423560909045922EXEC #140199425457600:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1853518045,tim=1423560909046084c CPU 限定的時間 e Elapsed time  p number of physical reads 物理讀的次數 cr number of buffers retrieved for CR reads   邏輯讀的資料區塊 cu number of buffers retrieved in current mode (current 模式讀取的資料區塊) mis cursor missed in the cache 庫緩衝中丟失的遊標, 硬解析次數 r number of rows processed 處理的行數 dep 遞迴深度 og optimizer mode 【1：all_rows, 2：first_rows, 3：rule, 4：choose】 plh plan hash value tim timestamp 時間戳記第3部分:執行過程中的發生的等待事件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 等待事件 ela 此操作消耗的時間 p3 block 塊號 trm timestamp 時間戳記第4部分:該遊標的執行計畫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 當前行源返回的行數 pid parent id of this row source 當前行源的父結點 id pos position in explain plan 執行計畫的位置 obj object id of row source (if this is a base object) op  the row source access operation*******************************************************************************************************************************************************************************************************************************3.使用 tkprof 命令翻譯 trace 檔案*************************************************************tkprof  /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2551.trc ./test.trcTKPROF: Release 11.2.0.4.0 - Development on 星期二 2月 10 17:47:28 2015Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.Trace file: /u01/app/oracle/diag/rdbms/orcl/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: 1853518045select count(*) from scott.tblorderscall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0          1          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0          1          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYSNumber of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max)  Row Source Operation---------- ---------- ----------  ---------------------------------------------------         1          1          1  SORT AGGREGATE (cr=1 pr=0 pw=0 time=110 us)       167        167        167   INDEX FULL SCAN PK_ORDERID (cr=1 pr=0 pw=0 time=76 us cost=1 size=0 card=167)(object id 89045)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           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0          1          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0          1          0           1Misses in library cache during parse: 1Elapsed times include waiting on following events:  Event waited on                             Times   Max. Wait  Total Waited  ----------------------------------------   Waited  ----------  ------------  SQL*Net message to client                       3        0.00          0.00  SQL*Net message from client                     3       20.55         39.10OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        0      0.00       0.00          0          0          0           0Execute      0      0.00       0.00          0          0          0           0Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        0      0.00       0.00          0          0          0           0Misses 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/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.