10046入门:使用 10046 查看执行计划并读懂 trace文件

*************************************************************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: [e-mail] (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:([e-mail] (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.