10046事件主要用来跟踪sql的执行，提供的信息比SQL_TRACE多，对SQL_TRACE是个补充
设置trace文件的标识,方便查找生成的trace文件：
HR@orcl>ALTER SESSION SET tracefile_identifier='10046';`
Session altered.
开启10046跟踪事件：
HR@orcl>ALTER SESSION SET EVENTS '10046 trace name context forever,level 12';
Session altered.
执行需要跟踪的sql：
HR@orcl>DELETE FROM departments WHERE department_id =0;
1 row deleted.
HR@orcl>commit;
Commit complete.
关闭10046跟踪事件：
HR@orcl>ALTER SESSION SET EVENTS '10046 trace name context off';
Session altered.
HR@orcl>
查看trace文件的存放目录
HR@orcl>select name, value from v$parameter where name = 'user_dump_dest';
NAME VALUE
------------------------------ --------------------------------------------------
user_dump_dest d:\app\chujf\diag\rdbms\orcl\orcl\trace
定位生成的trace文件，文件命中有开始定义的标识符10046：
HR@orcl>col tracefile format a80
HR@orcl>set line 500
HR@orcl>SELECT DISTINCT vm.sid,vp.pid,vp.tracefile
2 FROM v$mystat vm,v$session vs,v$process vp
3 WHERE vm.SID=vs.SID AND vs.PADDR = vp.addr;
SID PID TRACEFILE
---------- ---------- --------------------------------------------------------------------------------
173 34 d:\app\chujf\diag\rdbms\orcl\orcl\trace\orcl_ora_40940_10046.trc
HR@orcl>
使用tkprof工具将可读性较差的trace文件转换成可读性较好的
C:\Users\Chujf>cd D:\app\Chujf\diag\rdbms\orcl\orcl\trace
C:\Users\Chujf>d:
D:\app\Chujf\diag\rdbms\orcl\orcl\trace>tkprof orcl_ora_40940_10046.trc orcl_ora_40940_10046.sql sys=no
TKPROF: Release 11.2.0.1.0 - Development on Tue Jan 29 21:38:37 2019
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
D:\app\Chujf\diag\rdbms\orcl\orcl\trace>
在trace目录生成的文件orcl_ora_40940_10046.sql内容如下（注释为说明）：
TKPROF: Release 11.2.0.1.0 - Development on Tue Jan 29 21:38:37 2019
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: orcl_ora_40940_10046.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 --以秒为单位的调用（cpu+等待）时间
disk = number of physical reads of buffers from disk --从磁盘到缓冲区物理读的数量（数据块）
query = number of buffers gotten for consistent read --consistent模式下查询burrer数（select 一致读）
current = number of buffers gotten in current mode (usually for update) --current模式查询buffer数（dml 即时读）
rows = number of rows processed by the fetch or execute call --被fetch（select）或execute（dml）调用处理的行数
********************************************************************************
--delete语句部分
SQL ID: asxu4rnys9284
Plan Hash: 2526212926
DELETE FROM departments
WHERE
department_id =0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.08 0 41 0 0
Execute 1 0.00 0.01 0 2 11 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.04 0.10 0 43 11 1
/*
Parse：解析（找sqlid；检查语法、对象、权限；锁对象；创建和保存执行计划）
Execute:执行（select（确认选中的行） dml（执行更改数据的过程））
Fetch：取出（select（返回行到用户进程）dml（没有操作，只是返回执行结果））
*/
Misses in library cache during parse: 1 --解析过程在库缓存中找不到计划（导致硬解析的次数）
--Misses in library cache during execute 执行计划没有命中 和 计划在库缓存中失效（导致的硬解析次数） 执行调用时没有硬解析，无此行
Optimizer mode: ALL_ROWS --优化器模式，对应CBO基于成本的优化器；需要统计数据支持，否则自动采样；另有参数RULE（RBO）等
Parsing user id: 85 --解析用户id 在数据字典all_users有信息
Rows Row Source Operation --行源操作:每个行级操作返回的行数和额外行源信息，如物理读写
------- ---------------------------------------------------
0 DELETE DEPARTMENTS (cr=2 pr=0 pw=0 time=0 us)
1 INDEX UNIQUE SCAN DEPT_ID_PK (cr=1 pr=0 pw=0 time=0 us cost=0 size=10 card=1)(object id 73944)
/*
cr specifies consistent reads performed by the row source（行源操作执行逻辑一致读块数）
pr specifies physical reads performed by the row source（行源操作执行物理读块数）
pw specifies physical writes performed by the row source（行源操作执行物理写块数）
time specifies time in microseconds（以微秒为单位的估计运行时间）
cost （CBO执行计划计算开销）
size （预估返回的数据量，字节为单位）
card （预估被处理的行数）
object id （对象id，可从数据字典user_objects找详细信息）
*/
Elapsed times include waiting on following events: --总时间包括等待以下事件
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 5.25 5.25
********************************************************************************
--------------------------------------------commit语句部分
SQL ID: 23wm3kz7rps5y
Plan Hash: 0
commit
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.05 0 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.05 0 0 1 0
Misses in library cache during parse: 0
Parsing user id: 85
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file sync 1 0.00 0.00
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 338.32 338.32
********************************************************************************
------------------------------------------关闭跟踪事件语句部分
SQL ID: 0kjg1c2g4gdcr
Plan Hash: 0
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: 85
********************************************************************************
---------------------------------------tkprof 对所有非递归语句的总结
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.04 0.08 0 41 0 0
Execute 3 0.00 0.06 0 2 12 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.04 0.15 0 43 12 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 338.32 491.49
log file sync 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 34 0.03 0.02 0 0 0 0
Execute 152 0.09 0.13 0 3 1 1
Fetch 303 0.01 0.00 0 593 0 462
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 489 0.14 0.17 0 596 1 463
Misses in library cache during parse: 24
Misses in library cache during execute: 23
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 1 0.00 0.00
3 user SQL statements in session.
152 internal SQL statements in session.
155 SQL statements in session.
********************************************************************************
Trace file: orcl_ora_40940_10046.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
152 internal SQL statements in trace file.
155 SQL statements in trace file.
27 unique SQL statements in trace file.
2803 lines in trace file.
343 elapsed seconds in trace file.
通过sql_id找sql语句：
HR@orcl>select sql_text from v$sqlarea where sql_id = 'asxu4rnys9284';
SQL_TEXT
----------------------------------------------------------------------------------------------------
DELETE FROM departments WHERE department_id =0
原始的trace文件orcl_ora_40940_10046.trc内容如下：
Trace file d:\app\chujf\diag\rdbms\orcl\orcl\trace\orcl_ora_40940_10046.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
Windows NT Version V6.1 Service Pack 1
CPU : 4 - type 8664, 2 Physical Cores
Process Affinity : 0x0x0000000000000000
Memory (Avail/Total): Ph:1586M/7644M, Ph+PgF:5301M/15286M
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 34
Windows thread id: 40940, image: ORACLE.EXE (SHAD)
*** 2019-01-29 20:50:19.154
*** SESSION ID:(173.45743) 2019-01-29 20:50:19.154
*** CLIENT ID:() 2019-01-29 20:50:19.154
*** SERVICE NAME:(ORCL) 2019-01-29 20:50:19.154
*** MODULE NAME:(SQL*Plus) 2019-01-29 20:50:19.154
*** ACTION NAME:() 2019-01-29 20:50:19.154
/*
*/
WAIT #2: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=7364574083893
*** 2019-01-29 20:52:47.072
WAIT #2: nam='SQL*Net message from client' ela= 147913334 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=7364722021205
CLOSE #2:c=0,e=24,dep=0,type=1,tim=7364722021575
=====================
PARSING IN CURSOR #3 len=789 dep=1 uid=0 oct=3 lid=0 tim=7364722025968 hv=3159716790 ad='7ffbc91aac8' sqlid='7ng34ruy5awxq'
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,null,mod(trunc(i.pctthres$/256),256)),ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
END OF STMT
PARSE #3:c=15600,e=3322,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=7364722025966
BINDS #3:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=08 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=2c5e9168 bln=22 avl=04 flg=05
value=73943
Bind#1
No oacdef for this bind.
EXEC #3:c=0,e=59345,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=2542797530,tim=7364722085832
FETCH #3:c=0,e=1216,p=0,cr=9,cu=0,mis=0,r=1,dep=1,og=4,plh=2542797530,tim=7364722087179
152
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
