查看执行计划event 10046和tkprof-mysql教程-PHP中文网

上篇文章提到了用set autotrace和dbms_xplan去查看执行计划，下面我们将重点看看event 10046和tkprof来查看执行计划。 1 设置10046 event SQL> alter session set events '10046 trace name context forever ,level 12'; Session altered. SQL> select sum(o

上篇文章提到了用set autotrace和dbms_xplan去查看执行计划，下面我们将重点看看event 10046和tkprof来查看执行计划。

1 设置10046 event
SQL> alter session set events '10046 trace name context forever ,level 12';

Session altered.

SQL> select sum(object_id),sum(data_object_id) from t01;

SUM(OBJECT_ID) SUM(DATA_OBJECT_ID)
-------------- -------------------
1283335921 97173652

SQL> alter session set events '10046 trace name context off';

Session altered.

10046 event的raw trace文件：
Dump file g:\oracle\product\10.2.0\admin\ora10g\udump\ora10g_ora_1352.trc
Thu May 22 22:22:16 2014
ORACLE V10.2.0.4.0 - 64bit Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1
CPU : 4 - type 8664, 2 Physical Cores
Process Affinity : 0x0000000000000000
Memory (Avail/Total): Ph:4370M/7889M, Ph+PgF:10433M/15777M
Instance name: ora10g

Redo thread mounted by this instance: 1

Oracle process number: 115

Windows thread id: 1352, image: ORACLE.EXE (SHAD)
。。。
*** 2014-05-22 22:22:35.371
=====================
PARSING IN CURSOR #11 len=50 dep=0 uid=58 oct=3 lid=58 tim=12339600047 hv=887579624 ad='5d666250'
select sum(object_id),sum(data_object_id) from t01
END OF STMT
PARSE #11:c=0,e=1484,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=12339600040
BINDS #11: --10046 trace中还会记录bind value，这里由于没有使用bind，所以下面没有列出
EXEC #11:c=0,e=385,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12339602189
WAIT #11: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=12339602537
FETCH #11:c=15601,e=15187,p=0,cr=693,cu=0,mis=0,r=1,dep=0,og=1,tim=12339618068
WAIT #11: nam='SQL*Net message from client' ela= 370 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=12339619256
FETCH #11:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=12339619716
WAIT #11: nam='SQL*Net message to client' ela= 3 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=12339620145
WAIT #11: nam='SQL*Net message from client' ela= 8040398 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=12347660914
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=693 pr=0 pw=0 time=15180 us)'
STAT #11 id=2 cnt=50070 pid=1 pos=1 obj=51887 op='TABLE ACCESS FULL T01 (cr=693 pr=0 pw=0 time=84 us)'

下面小鱼将结合部分资料对这个10046 event进行解读：
PARSING IN CURSOR #11 len=50 dep=0 uid=58 oct=3 lid=58 tim=12339600047 hv=887579624 ad='5d666250'
先看上面的的parsing in cursor部分：
其中的parsing in cursor表示的游标编号，这里是11
Len表示的是被解析的sql语句长度
Dep表示的递归sql语句的深度
Uid是user_id，对应于dba_users的user_id
Oct表示oracle command type类型
Lid表示私有用户id
Tim表示时间戳
Hv表示的sql的hash_value
Ad表示的sql的address

BINDS #11: --10046 trace中还会记录bind value，这里由于没有使用bind，所以下面没有列出

再来看parse、exec和fetch部分：
PARSE #11:c=0,e=1484,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=12339600040
EXEC #11:c=0,e=385,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=12339602189
FETCH #11:c=15601,e=15187,p=0,cr=693,cu=0,mis=0,r=1,dep=0,og=1,tim=12339618068
FETCH #11:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=12339619716
C表示消耗的cpu time
E表示消耗的事件
P表示物理读
Cr表示一致性读
Mis表示硬解析次数
R表示处理的行数
Dep表示递归sql的深度
Og optimizer goal表示优化器模式
Time表示时间戳

Stat部分：
STAT #11 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=693 pr=0 pw=0 time=15180 us)'
STAT #11 id=2 cnt=50070 pid=1 pos=1 obj=51887 op='TABLE ACCESS FULL T01 (cr=693 pr=0 pw=0 time=84 us)'
Id表示执行计划id
Cnt表示cardinality
Pid表示行源号的父号
Pos执行计划中的位置
Obj表示的是对象的object_id
Op表示执行计划的中返回方式
Cr表示的一致性读取
Pr表示的物理读
Pw表示的物理写
Time表示消耗的时间，这里的us是微妙，1s=1000ms=1000*1000us

STAT包含了完整的执行计划，10046 event trace也能看见完整的执行计划，还能看见各个执行步骤消耗的步骤，比如一致性读、物理读写，消耗的时间，相比dbms_xplan、autotrace更加清晰和明了。

Level 12 10046 trace文件中还记录了一个比较重要的信息就是等待事件，分别记录了sql解析，执行和获取数据时各自的等待事件，比如上述这个sql语句还记录了sql语句执行的过程（解析-执行-获取数据）的伴随着sql*net message to client和sql*net message from client等待。

大家如果能直接看懂10046 event的trace更好，如果看不懂oracle也推出了tkprof用来简化原始的10046 event trace文件，使用办法也很简单。
C:\Users\Administrator>tkprof
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 PLAN.
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.
waits=yes|no Record summary for any wait events found in the trace file.
sort=option Set of zero or more of the following sort options:
prscnt number of times parse was called
prscpu cpu time parsing
prsela elapsed time parsing
prsdsk number of disk reads during parse
prsqry number of buffers for consistent read during parse
prscu number of buffers for current read during parse
prsmis number of misses in library cache during parse
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
fchcnt number of times fetch was called
fchcpu cpu time spent fetching
fchela elapsed time fetching
fchdsk number of disk reads during fetch
fchqry number of buffers for consistent read during fetch
fchcu number of buffers for current read during fetch
fchrow number of rows fetched
userid userid of user that parsed the cursor

小鱼一般喜欢加上sys=no和aggregate=no，sys默认是yes，意为也捕捉sys用户的操作，而aggreagte是将相同的sql语句集合评估。
C:\Users\Administrator>tkprof G:\oracle\product\10.2.0\admin\ora10g\udump\ora10g_ora_1352.trc g:\tkprof_10046.txt sys=no aggregate=no explain=xiaoyu/xiaoyu

TKPROF: Release 10.2.0.4.0 - Production on Thu May 22 23:39:57 2014

生成的tkprof文件如下：

TKPROF: Release 10.2.0.4.0 - Production on Thu May 22 23:39:57 2014

Trace file: G:\oracle\product\10.2.0\admin\ora10g\udump\ora10g_ora_1352.trc
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed 执行的次数
cpu = cpu time in seconds executing 消耗cpu时间，单位秒
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 返回的rows
********************************************************************************

select sum(object_id),sum(data_object_id)
from
t01

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 0 693 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 693 0 1

Misses in library cache during parse: 1 --miss in library cache表示的是硬解析
Optimizer mode: ALL_ROWS --优化器模式
Parsing user id: 58 --解析的userid

--执行计划，其中rows表示的每步执行步骤对应的cardinality，cr表示的消耗的一致性读取，pr表示的物理读，pw表示物理写，time表示消耗的时间
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=693 pr=0 pw=0 time=15180 us)
50070 TABLE ACCESS FULL T01 (cr=693 pr=0 pw=0 time=84 us)

在sql语句中的等待事件。
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 8.04 8.04
********************************************************************************

alter session set events '10046 trace name context off'

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0
Parsing user id: 58

下面是系统递归sql语句和非递归sql语句的消耗的资源和等待事件，递归sql语句表示的是sql语句执行过程中需要读取一些数据字典而产生的sql语句
********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.01 0.01 0 693 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.01 0 693 0 1

Misses in library cache during parse: 1

Elapsed 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 18.54 26.58

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: G:\oracle\product\10.2.0\admin\ora10g\udump\ora10g_ora_1352.trc
Trace file compatibility: 10.01.00
Sort options: default

1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
50 lines in trace file.
8 elapsed seconds in trace file.

原文地址：查看执行计划event 10046和tkprof, 感谢原作者分享。