10046事件和tkprof命令
来源：互联网 发布：安徽航信网络发票 编辑：程序博客网 时间：2024/06/06 12:48
一.在ORACLE数据库里，我们通常可以使用如下这些方法(包括但不限于)得到目标SQL的执行计划：
1，explain plan
2，DBMS_XPLAN包
3，SQLPLUS中的AUTOTRACE开关
4，10046事件
5，10053事件
6，AWR报告或者STATSPACK报告
前面的四种方法比较普遍。
二.下面介绍下第四种即10046事件如何得到目标SQL的执行计划
10046与使用explain plan命令，DBMS_XPLAN包和AUTOTRACE开关的不同之处在于，所得到的执行计划中明确显示了目标SQL的实际执行计划中每一个步骤所消耗的逻辑度(cr:consistent read)，物理读(pr:physical read)和花费的时间(time)。
用10046事件得到的目标SQL的执行计划只需要依次执行下面三步：
- 在当前SESSION中激活10046事件
- 在此SESSION中执行目标SQL
- 在此SESSION中关闭10046事件
执行完上面的步骤后，ORACLE会将目标SQL的执行计划和明细资源消耗写入此SESSION对应的TRACE文件中，此文件一把会在USER_DUMP_DEST目录下，其命名格式是： 实例名_ora_当前SESSION的SPID.trc.
通常可以用下面两种方法激活10046事件：
- 在当前SESSION中执行alter session set events '10046 trace name context forever,level 12'
- 在当前SESSION中执行oradebug event 10046 trace name context forever,level 12
对应的在当前SESSION中关闭10046事件的方法为：
- alter session set events '10046 trace name context off'
- oradebug event 10046 trace name context off
10046生成的TRACE文件，我们称之为裸文件(raw trace),ORACCLE 提供了工具TKPROF来查看他。下面我们来做一个实验来演示如何通过10046事件来获取和查看目标SQL的实际执行计划
三.以下面sql来说明10046事件：
SELECT e.last_name || ' ,' || e.first_name AS full_name,
e.phone_number,
e.email,
e.department_id,
d.department_id,
c.country_name,
l.city,
l.state_province,
r.region_name
FROM hr.employees e,
hr.departments d,
hr.countries c,
hr.locations l,
hr.regions r
WHERE e.department_id = d.department_id
AND d.location_id = l.location_id
AND l.country_id = c.country_id
AND c.region_id = r.region_id;
SQL> oradebug help
HELP [command] Describe one or all commands
SETMYPID Debug current process
SETOSPID <ospid> Set OS pid of process to debug
SETORAPID <orapid> ['force'] Set Oracle pid of process to debug
SHORT_STACK Dump abridged OS stack
DUMP <dump_name> <lvl> [addr] Invoke named dump
DUMPSGA [bytes] Dump fixed SGA
DUMPLIST Print a list of available dumps
EVENT <text> Set trace event in process
SESSION_EVENT <text> Set trace event in session
DUMPVAR <p|s|uga> <name> [level] Print/dump a fixed PGA/SGA/UGA variable
DUMPTYPE <address> <type> <count> Print/dump an address with type info
SETVAR <p|s|uga> <name> <value> Modify a fixed PGA/SGA/UGA variable
PEEK <addr> <len> [level] Print/Dump memory
POKE <addr> <len> <value> Modify memory
WAKEUP <orapid> Wake up Oracle process
SUSPEND Suspend execution
RESUME Resume execution
FLUSH Flush pending writes to trace file
CLOSE_TRACE Close trace file
TRACEFILE_NAME Get name of trace file
LKDEBUG Invoke global enqueue service debugger
NSDBX Invoke CGS name-service debugger
-G <Inst-List | def | all> Parallel oradebug command prefix
-R <Inst-List | def | all> Parallel oradebug prefix (return output
SETINST <instance# .. | all> Set instance list in double quotes
SGATOFILE <SGA dump dir> Dump SGA to file; dirname in double quotes
DMPCOWSGA <SGA dump dir> Dump & map SGA as COW; dirname in double quotes
MAPCOWSGA <SGA dump dir> Map SGA as COW; dirname in double quotes
HANGANALYZE [level] [syslevel] Analyze system hang
FFBEGIN Flash Freeze the Instance
FFDEREGISTER FF deregister instance from cluster
FFTERMINST Call exit and terminate instance
FFRESUMEINST Resume the flash frozen instance
FFSTATUS Flash freeze status of instance
SKDSTTPCS <ifname> <ofname> Helps translate PCs to names
WATCH <address> <len> <self|exist|all|target> Watch a region of memory
DELETE <local|global|target> watchpoint <id> Delete a watchpoint
SHOW <local|global|target> watchpoints Show watchpoints
CORE Dump core without crashing process
IPC Dump ipc information
UNLIMIT Unlimit the size of the trace file
PROCSTAT Dump process statistics
CALL <func> [arg1] ... [argn] Invoke function with arguments
(a)SQL> oradebug setmypid
Statement processed.
（b）SQL> oradebug event 10046 trace name context forever,level 12
Statement processed.
（c）SELECT e.last_name || ' ,' || e.first_name AS full_name,
e.phone_number,e.email,
e.department_id,
d.department_id,
c.country_name,
l.city,
l.state_province,
r.region_name
FROM hr.employees e,
hr.departments d,
hr.countries c,
hr.locations l,
hr.regions r
WHERE e.department_id = d.department_id
AND d.location_id = l.location_id
AND l.country_id = c.country_id
18 AND c.region_id = r.region_id;
FULL_NAME PHONE_NUMBER EMAIL DEPARTMENT_ID DEPARTMENT_ID COUNTRY_NAME CITY
----------------------------------------------- -------------------- ------------------------- ------------- ------------- ---------------------------------------- ------------------------------
STATE_PROVINCE REGION_NAME
------------------------- -------------------------
OConnell ,Donald 650.507.9833 DOCONNEL 5050 United States of America South San Francisco
California Americas
106 rows selected.
用oradebug tracefile_name命令就可以一目了然的看到当前session激活10046事件后所对应的trace文件的路径和名称：
SQL> oradebug tracefile_name;
/u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc
关掉10046事件：
SQL> oradebug event 10046 trace name context off
Statement processed.
查看/u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc文件
[oracle@node1 ~]$ cat /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc
Trace file /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1
System name: Linux
Node name: node1
Release: 2.6.32-300.10.1.el5uek
Version: #1 SMP Wed Feb 22 17:37:40 EST 2012
Machine: x86_64
VM name: VMWare Version: 6
Instance name: MECBS1
Redo thread mounted by this instance: 1
Oracle process number: 36
Unix process pid: 7389, image: oracle@node1 (TNS V1-V3)--
*** 2014-11-25 09:44:22.203
*** SESSION ID:(13.9) 2014-11-25 09:44:22.203
*** CLIENT ID:() 2014-11-25 09:44:22.203
*** SERVICE NAME:(SYS$USERS) 2014-11-25 09:44:22.203
*** MODULE NAME:(sqlplus@node1 (TNS V1-V3)) 2014-11-25 09:44:22.203
*** ACTION NAME:() 2014-11-25 09:44:22.203
Processing Oradebug command 'event 10046 trace name context forever,level 12'
*** 2014-11-25 09:57:21.754
Processing Oradebug command 'tracefile_name'
PARSING IN CURSOR #140134982066512 len=497 dep=0 uid=0 oct=3 lid=0 tim=1416880688267812 hv=940757165 ad='720722b8' sqlid='1xhyf6hw15n5d'
SELECT e.last_name || ' ,' || e.first_name AS full_name,
e.phone_number,
e.email,
e.department_id,
d.department_id,
c.country_name,
l.city,
l.state_province,
r.region_name
FROM hr.employees e,
hr.departments d,
hr.countries c,
hr.locations l,
hr.regions r
WHERE e.department_id = d.department_id
AND d.location_id = l.location_id
AND l.country_id = c.country_id
AND c.region_id = r.region_id
END OF STMT
PARSE #140134982066512:c=43992,e=88497,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=231184628,tim=1416880688267797
FETCH #140134982066512:c=0,e=226,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=231184628,tim=1416880688447535
c＝cpu消耗时间，单位是毫秒
e＝逃离时间，4.723秒
p=物理读次数
cr＝consistent read一致性读
cu＝db block gets当前读
mis＝软解析的次数，错过缓存的次数。
r＝表示这个SQL取到的行数
dep＝递归调用的深度
og＝optimizer mode 1表示CBO
tim＝时间戳
STAT #140134982066512 id=1 cnt=106 pid=0 pos=1 obj=0 op='HASH JOIN (cr=31 pr=0 pw=0 time=5298 us cost=11 size=10600 card=106)'
STAT #140134982066512 id=2 cnt=27 pid=1 pos=1 obj=0 op='HASH JOIN (cr=18 pr=0 pw=0 time=4554 us cost=8 size=1593 card=27)'
STAT #140134982066512 id=3 cnt=27 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=12 pr=0 pw=0 time=4857 us cost=5 size=1215 card=27)'
STAT #140134982066512 id=4 cnt=27 pid=3 pos=1 obj=0 op='MERGE JOIN (cr=8 pr=0 pw=0 time=4148 us cost=5 size=810 card=27)'
STAT #140134982066512 id=5 cnt=19 pid=4 pos=1 obj=88049 op='TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=0 pw=0 time=490 us cost=2 size=529 card=23)'
STAT #140134982066512 id=6 cnt=19 pid=5 pos=1 obj=88141 op='INDEX FULL SCAN LOC_ID_PK (cr=1 pr=0 pw=0 time=99 us cost=1 size=0 card=23)'
STAT #140134982066512 id=7 cnt=27 pid=4 pos=2 obj=0 op='SORT JOIN (cr=6 pr=0 pw=0 time=3445 us cost=3 size=189 card=27)'
STAT #140134982066512 id=8 cnt=27 pid=7 pos=1 obj=0 op='VIEW index$_join$_002 (cr=6 pr=0 pw=0 time=3294 us cost=2 size=189 card=27)'
STAT #140134982066512 id=9 cnt=27 pid=8 pos=1 obj=0 op='HASH JOIN (cr=6 pr=0 pw=0 time=3291 us)'
STAT #140134982066512 id=10 cnt=27 pid=9 pos=1 obj=88147 op='INDEX FAST FULL SCAN DEPT_ID_PK (cr=3 pr=0 pw=0 time=198 us cost=1 size=189 card=27)'
STAT #140134982066512 id=11 cnt=27 pid=9 pos=2 obj=88146 op='INDEX FAST FULL SCAN DEPT_LOCATION_IX (cr=3 pr=0 pw=0 time=129 us cost=1 size=189 card=27)'
STAT #140134982066512 id=12 cnt=27 pid=3 pos=2 obj=88034 op='INDEX UNIQUE SCAN COUNTRY_C_ID_PK (cr=4 pr=0 pw=0 time=126 us cost=0 size=15 card=1)'
STAT #140134982066512 id=13 cnt=4 pid=2 pos=2 obj=88050 op='TABLE ACCESS FULL REGIONS (cr=6 pr=0 pw=0 time=66 us cost=3 size=56 card=4)'
STAT #140134982066512 id=14 cnt=107 pid=1 pos=2 obj=88047 op='TABLE ACCESS FULL EMPLOYEES (cr=13 pr=0 pw=0 time=51 us cost=3 size=4387 card=107)'
WAIT #140134982066512: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880688504047
*** 2014-11-25 09:59:20.611
WAIT #140134982066512: nam='SQL*Net message from client' ela= 72107005 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760611195
WAIT #140134982066512: nam='SQL*Net break/reset to client' ela= 330 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=1416880760612011
WAIT #140134982066512: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760612149
WAIT #140134982066512: nam='SQL*Net message from client' ela= 454 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760621215
CLOSE #140134982066512:c=0,e=37,dep=0,type=0,tim=1416880760621478
=====================
PARSING IN CURSOR #140134982066512 len=497 dep=0 uid=0 oct=3 lid=0 tim=1416880760622734 hv=940757165 ad='720722b8' sqlid='1xhyf6hw15n5d'
SELECT e.last_name || ' ,' || e.first_name AS full_name,
e.phone_number,
e.email,
e.department_id,
d.department_id,
c.country_name,
l.city,
l.state_province,
r.region_name
FROM hr.employees e,
hr.departments d,
hr.countries c,
hr.locations l,
hr.regions r
WHERE e.department_id = d.department_id
AND d.location_id = l.location_id
AND l.country_id = c.country_id
AND c.region_id = r.region_id
END OF STMT
PARSE #140134982066512:c=1000,e=1037,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=231184628,tim=1416880760622731
EXEC #140134982066512:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=231184628,tim=1416880760623584
WAIT #140134982066512: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760623673
FETCH #140134982066512:c=6999,e=6016,p=0,cr=20,cu=0,mis=0,r=1,dep=0,og=1,plh=231184628,tim=1416880760629761
WAIT #140134982066512: nam='SQL*Net message from client' ela= 1929 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760632016
WAIT #140134982066512: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760632259
FETCH #140134982066512:c=0,e=366,p=0,cr=5,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760632560
WAIT #140134982066512: nam='SQL*Net message from client' ela= 3900 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760636614
WAIT #140134982066512: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760637086
FETCH #140134982066512:c=0,e=237,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760637245
WAIT #140134982066512: nam='SQL*Net message from client' ela= 14483 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760652143
WAIT #140134982066512: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760654704
FETCH #140134982066512:c=0,e=307,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760654935
WAIT #140134982066512: nam='SQL*Net message from client' ela= 7584 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760662652
WAIT #140134982066512: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760663042
FETCH #140134982066512:c=0,e=221,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760663181
WAIT #140134982066512: nam='SQL*Net message from client' ela= 7556 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760672175
WAIT #140134982066512: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760672646
FETCH #140134982066512:c=0,e=296,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760672860
WAIT #140134982066512: nam='SQL*Net message from client' ela= 17180 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760690219
WAIT #140134982066512: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760691565
FETCH #140134982066512:c=1000,e=479,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760691739
WAIT #140134982066512: nam='SQL*Net message from client' ela= 8436 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760700515
WAIT #140134982066512: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760701006
FETCH #140134982066512:c=0,e=448,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=231184628,tim=1416880760701149
WAIT #140134982066512: nam='SQL*Net message from client' ela= 4130 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760705532
FETCH #140134982066512:c=0,e=174,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=231184628,tim=1416880760706102
STAT #140134982066512 id=1 cnt=106 pid=0 pos=1 obj=0 op='HASH JOIN (cr=31 pr=0 pw=0 time=6009 us cost=11 size=10600 card=106)'
STAT #140134982066512 id=2 cnt=27 pid=1 pos=1 obj=0 op='HASH JOIN (cr=18 pr=0 pw=0 time=5022 us cost=8 size=1593 card=27)'
STAT #140134982066512 id=3 cnt=27 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=12 pr=0 pw=0 time=5158 us cost=5 size=1215 card=27)'
STAT #140134982066512 id=4 cnt=27 pid=3 pos=1 obj=0 op='MERGE JOIN (cr=8 pr=0 pw=0 time=4447 us cost=5 size=810 card=27)'
STAT #140134982066512 id=5 cnt=19 pid=4 pos=1 obj=88049 op='TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=0 pw=0 time=426 us cost=2 size=529 card=23)'
STAT #140134982066512 id=6 cnt=19 pid=5 pos=1 obj=88141 op='INDEX FULL SCAN LOC_ID_PK (cr=1 pr=0 pw=0 time=161 us cost=1 size=0 card=23)'
STAT #140134982066512 id=7 cnt=27 pid=4 pos=2 obj=0 op='SORT JOIN (cr=6 pr=0 pw=0 time=3858 us cost=3 size=189 card=27)'
STAT #140134982066512 id=8 cnt=27 pid=7 pos=1 obj=0 op='VIEW index$_join$_002 (cr=6 pr=0 pw=0 time=3786 us cost=2 size=189 card=27)'
STAT #140134982066512 id=9 cnt=27 pid=8 pos=1 obj=0 op='HASH JOIN (cr=6 pr=0 pw=0 time=3730 us)'
STAT #140134982066512 id=10 cnt=27 pid=9 pos=1 obj=88147 op='INDEX FAST FULL SCAN DEPT_ID_PK (cr=3 pr=0 pw=0 time=524 us cost=1 size=189 card=27)'
STAT #140134982066512 id=11 cnt=27 pid=9 pos=2 obj=88146 op='INDEX FAST FULL SCAN DEPT_LOCATION_IX (cr=3 pr=0 pw=0 time=313 us cost=1 size=189 card=27)'
STAT #140134982066512 id=12 cnt=27 pid=3 pos=2 obj=88034 op='INDEX UNIQUE SCAN COUNTRY_C_ID_PK (cr=4 pr=0 pw=0 time=127 us cost=0 size=15 card=1)'
STAT #140134982066512 id=13 cnt=4 pid=2 pos=2 obj=88050 op='TABLE ACCESS FULL REGIONS (cr=6 pr=0 pw=0 time=210 us cost=3 size=56 card=4)'
STAT #140134982066512 id=14 cnt=107 pid=1 pos=2 obj=88047 op='TABLE ACCESS FULL EMPLOYEES (cr=13 pr=0 pw=0 time=67 us cost=3 size=4387 card=107)'
WAIT #140134982066512: nam='SQL*Net message to client' ela= 10 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880760718531
*** 2014-11-25 10:00:44.237
WAIT #140134982066512: nam='SQL*Net message from client' ela= 83518465 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880844237161
CLOSE #140134982066512:c=0,e=31,dep=0,type=0,tim=1416880844237781
*** 2014-11-25 10:00:44.238
Processing Oradebug command 'tracefile_name'
** 2014-11-25 10:00:44.238
Oradebug command 'tracefile_name' console output:
/u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc
WAIT #0: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880844238709
*** 2014-11-25 10:01:15.108
WAIT #0: nam='SQL*Net message from client' ela= 30870019 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1416880875108822
*** 2014-11-25 10:01:15.109
Processing Oradebug command 'event 10046 trace name context off'
上面文件格式比较乱，不方便阅读，我们用tkprof格式化一下：
output = /home/oracle/MECBS1_ora_7389.trc.tkf
TKPROF: Release 11.2.0.4.0 - Development on Tue Nov 25 10:03:20 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
[oracle@even ~]$ tkprof /u01/app/oracle/admin/OMR/udump/omr_ora_16192.trc /u01/app/oracle/admin/OMR/udump/watson_omr_ora_16192_tkprof.trc
TKPROF: Release 10.2.0.1.0 - Production on Fri Dec 6 12:57:28 2013
Copyright (c) 1982, 2005, Oracle. All rights reserved.
以下是格式化的trace文件：
[oracle@node1 ~]$ cat MECBS1_ora_7389.trc.tkfTKPROF: Release 11.2.0.4.0 - Development on Tue Nov 25 10:03:20 2014
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.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 －－返回的行数
********************************************************************************
SELECT e.last_name || ' ,' || e.first_name AS full_name,
e.phone_number,
e.email,
e.department_id,
d.department_id,
c.country_name,
l.city,
l.state_province,
r.region_name
FROM hr.employees e,
hr.departments d,
hr.countries c,
hr.locations l,
hr.regions r
WHERE e.department_id = d.department_id
AND d.location_id = l.location_id
AND l.country_id = c.country_id
AND c.region_id = r.region_id
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.04 0.08 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 18 0.01 0.01 0 62 0 212
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 22 0.06 0.10 0 62 0 212
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 2
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
106 106 106 HASH JOIN (cr=31 pr=0 pw=0 time=5654 us cost=11 size=10600 card=106)
27 27 27 HASH JOIN (cr=18 pr=0 pw=0 time=4788 us cost=8 size=1593 card=27)
27 27 27 NESTED LOOPS (cr=12 pr=0 pw=0 time=5008 us cost=5 size=1215 card=27)
27 27 27 MERGE JOIN (cr=8 pr=0 pw=0 time=4298 us cost=5 size=810 card=27)
19 19 19 TABLE ACCESS BY INDEX ROWID LOCATIONS (cr=2 pr=0 pw=0 time=458 us cost=2 size=529 card=23)
19 19 19 INDEX FULL SCAN LOC_ID_PK (cr=1 pr=0 pw=0 time=130 us cost=1 size=0 card=23)(object id 88141)
27 27 27 SORT JOIN (cr=6 pr=0 pw=0 time=3652 us cost=3 size=189 card=27)
27 27 27 VIEW index$_join$_002 (cr=6 pr=0 pw=0 time=3540 us cost=2 size=189 card=27)
27 27 27 HASH JOIN (cr=6 pr=0 pw=0 time=3510 us)
27 27 27 INDEX FAST FULL SCAN DEPT_ID_PK (cr=3 pr=0 pw=0 time=361 us cost=1 size=189 card=27)(object id 88147)
27 27 27 INDEX FAST FULL SCAN DEPT_LOCATION_IX (cr=3 pr=0 pw=0 time=221 us cost=1 size=189 card=27)(object id 88146)
27 27 27 INDEX UNIQUE SCAN COUNTRY_C_ID_PK (cr=4 pr=0 pw=0 time=126 us cost=0 size=15 card=1)(object id 88034)
4 4 4 TABLE ACCESS FULL REGIONS (cr=6 pr=0 pw=0 time=138 us cost=3 size=56 card=4)
107 107 107 TABLE ACCESS FULL EMPLOYEES (cr=13 pr=0 pw=0 time=59 us cost=3 size=4387 card=107)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 19 0.00 0.00
SQL*Net message from client 19 83.51 155.85
SQL*Net break/reset to client 1 0.00 0.00
********************************************************************************
汇总的结果
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS －－非递归调用的操作统计
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.04 0.08 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 18 0.01 0.01 0 62 0 212
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 22 0.06 0.10 0 62 0 212
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 21 0.00 0.00
SQL*Net message from client 21 83.51 198.30
SQL*Net break/reset to client 1 0.00 0.00
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: /u01/app/oracle/diag/rdbms/mecbs/MECBS1/trace/MECBS1_ora_7389.trc
Trace file compatibility: 11.1.0.7
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.
1 unique SQL statements in trace file.
214 lines in trace file.
72 elapsed seconds in trace file
以下是通过explain plan得到的执行计划：
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 231184628
----------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 106 | 10600 | 11 (10)| 00:00:01 |
|* 1 | HASH JOIN | | 106 | 10600 | 11 (10)| 00:00:01 |
|* 2 | HASH JOIN | | 27 | 1593 |8 (13)| 00:00:01 |
| 3 | NESTED LOOPS | | 27 | 1215 |5 (20)| 00:00:01 |
| 4 | MERGE JOIN | | 27 | 810 |5 (20)| 00:00:01 |
| 5 | TABLE ACCESS BY INDEX ROWID| LOCATIONS | 23 | 529 |2 (0)| 00:00:01 |
| 6 | INDEX FULL SCAN | LOC_ID_PK | 23 | | 1 (0)| 00:00:01 |
|* 7 | SORT JOIN | | 27 | 189 |3 (34)| 00:00:01 |
| 8 | VIEW | index$_join$_002 |27 | 189 | 2 (0)| 00:00:01 |
|* 9 | HASH JOIN | | | | | |
| 10 | INDEX FAST FULL SCAN| DEPT_ID_PK |27 | 189 | 1 (0)| 00:00:01 |
| 11 | INDEX FAST FULL SCAN| DEPT_LOCATION_IX | 27 | 189 |1 (0)| 00:00:01 |
|* 12 | INDEX UNIQUE SCAN | COUNTRY_C_ID_PK |1 | 15 |0 (0)| 00:00:01 |
| 13 | TABLE ACCESS FULL | REGIONS | 4 |56 | 3 (0)| 00:00:01 |
| 14 | TABLE ACCESS FULL | EMPLOYEES | 107 | 4387 | 3 (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("E"."DEPARTMENT_ID"="D"."DEPARTMENT_ID")
2 - access("C"."REGION_ID"="R"."REGION_ID")
7 - access("D"."LOCATION_ID"="L"."LOCATION_ID")
filter("D"."LOCATION_ID"="L"."LOCATION_ID")
9 - access(ROWID=ROWID)
12 - access("L"."COUNTRY_ID"="C"."COUNTRY_ID")
- 10046事件和tkprof命令
- 10046事件与tkprof命令
- 10046事件与tkprof命令
- 命令TKPROF
- TKPROF 命令语法
- SQL优化及性能诊断(10046事件/tkprof)
- tkprof和sql trace
- sql_trace和tkprof工具
- Tkprof
- tkprof
- Tkprof
- Tkprof工具介绍和分析
- Tkprof工具介绍和分析
- Tkprof工具介绍和分析
- 未知命令'tkprof ‘。。。。。。其余行忽略
- tkprof命令格式化分析跟踪文件
- sql trace、10046、tkprof介绍
- 使用SQL TRACE 实用工具和TKPROF
- Objective-C Runtime 运行时之二：成员变量与属性
- Struts2之文件下载
- c#里SQL数据库里取出来的数值判断是否为空
- Android 触摸屏（TP）问题现象分析和解决方法汇总
- Downloadmanager 状态整理
- 10046事件和tkprof命令
- Android Fragment 真正的完全解析
- IAR 6.3中intrinsics.h与core_cm3.h 中的兼容错误解决方法
- 基于Jquery+Ajax+Json+高效分页
- Jquery 甘特图 插件 jQuery.Gantt
- hashmap遍历
- 《Linux设备驱动程序》——USB驱动程序
- OPENSSL中RSA私钥文件（PEM格式）解析
- Objective-C Runtime 运行时之三：方法与消息
