SQL_TRACE和10046事件详解
2017-07-10 22:55
477 查看
sql_trace和10046事件都是我们在优化sql上面应用的非常多的工具，我们可以使用这两个工具知道当前正在执行的sql究竟在做什么
一，SQL_TRACE： SQL_TRACE命令会将执行的整个过程输出到一个trace文件，我通过阅读这个trace文件来了解这个sql在执行过程中Oracle究竟做了哪些事情
1）确定trace文件的路径
启用sql_trace前我们首先要确定跟踪文件的存放位置，即user_dump_dest下
SQL> show parameter user_dump_dest;
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /u01/opt/oracle/admin/orcl
/udump
sql trace文件固定格式为<user_dump_dest>/<instance_name>_ora_<backgroudProcessID>.trc
其中user_dump_dest,instance_name的值可以通过show命令得到，backgroudProcessID的值就需要首先获取session的sid然后根据sid的值查询v$session中进程的地址，然后根据进程地址找到processID，在11G以前可以通过下面这个语句获取当前session的sql_trace文件的路径
SQL> select
a.value || '/' || b.instance_name || '_ora_' || c.spid || '.trc' trace_file
from
(select value from v$parameter where name= 'user_dump_dest') a,
(select instance_name from v$instance) b,
(select spid from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat))) c;
TRACE_FILE
--------------------------------------------------------------------------------
/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810.trc
在11g以后v$process视图里面tracefile 字段直接给出了这个值，因此不需要写上面那么麻烦的语句
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_29991.trc
另外也可以手工更改产生trace文件的名称例如
SQL> alter session set tracefile_identifier='mytrace'
执行这条语句后就会在原有的tracename上加上_mytrace例如前面查出来的/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810.trc就会变成/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810_mytrace.trc这时我们只需要到user_dump_dest的路径下通过ls命令匹配关键字mytrace就可以了，就没有必要去写sql查询了。
2）启用sql_trace
启用sql_trace可以通过从instance级别和session级别，我们知道每个session都会有一个trace文件，因此在实例级别启用如果session越多将暂用的系统资源越多，除非有特殊的需求。
下面的语句可以启用实例级别的trace
SQL> alter system set sql_trace=true
SQL> show parameter sql_trace
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
sql_trace boolean TURE
从session级别启动有两种方式，第一跟踪当前的session，第二跟踪其它的session，我们只需要确定备跟踪会话的sid和serial#的值就可以了
当前session：
SQL> alter system set sql_trace=ture;
其它session：
例如确定了session id=138然后查询v$session获取serial#
SQL> select sid,serial# from v$session where sid=138;
SID SERIAL#
---------- ----------
138 2397
然后执行下面的包来跟踪这个session
SQL> execute dmbs_system.set_sql_trace_in_session(138,2397,true)
停止：
SQL> execute dmbs_system.set_sql_trace_in_session(138,2397,false)
二，TKPROF工具
默认生成的trace文件的可读性是比较差的，我们通常会用TKPROF这个工具来格式化在个trace文件。tkprof工具是oracle自带的一个工具，用于处理原始的trace文件，它的主要作用是合并汇总trace文件中的一些项，规范化文件格式，使得文件具有可读性，下面是简单的格式化一个文件
[oracle@localhost trace]$ tkprof RBKSAFARI_ora_1302.trc new.txt
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:08:57 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
-----------------------------------------------------
下面来执行一条sql语句使用，看看trace文件中的内容信息
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_30598.trc
SQL> alter session set sql_trace=true;
Session altered.
SQL> select * from test where id=100;
使用tkprof工具格式化RBKSAFARI_ora_30598.trc这个文件
[oracle@localhost trace]$ tkprof RBKSAFARI_ora_30598.trc mytrace.txt
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:17:25 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
用vi打开如下
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:17:25 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: RBKSAFARI_ora_30598.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
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
********************************************************************************
trace文件头部的信息描述了tkprof的版本，以及报告中一些列的定义，在下面的报告中，每一条sql都包含了这条sql执行过程的所有信息，对于任何一条sql都应该包含3个步骤（对应下表的call列）
分析（parse）：SQL的分析阶段
执行（execute）：SQL的执行阶段
数据提取（Fetch）：数据提取阶段
横向的列除了call之外，还包含了一下信息：
count：计算器，表示当前的操作被执行了多少次。
cpu：当前的操作消耗的cpu时间（单位秒）
Elapsed: 当前的操作一共用时多少（包括cpu事件和等待时间）
Disk：当前操作的物理读（磁盘i/o次数）
Query：当前操作的一致性读方式读取的数据块数（通常是查询）
Current：当前操作的current的方式读取的数据库数（通常是修改数据块使用的方式）
Rows：当前操作处理的数据记录数
SQL ID: 4tk6t8tfsfqbf
Plan Hash: 0
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 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 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************
下面才是我们需要的信息，我们执行的那条查询sql的trace信息
SQL ID: d3gtqbsdqbbwq
Plan Hash: 4274779609
select *
from
test where id=100
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.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 3 0 1
我们看到，这条sql语句被分析了一次，执行了一次，数据提取了2次，cpu和elpased都为0是因为这个表暂用的数据比较少，可以看到一共查询3个块，没有物理读，说明这个3个块已经缓冲到了buffer cache中，最后返回了1行的记录
Misses in library cache during parse: 1 --说明在shared pool中没有命中，说明这是一次硬分析
Optimizer mode: ALL_ROWS --当前优化器模式为CBO ALL_ROS
Parsing user id: SYS --分析用户id
下面是这条sql语句的具体执行计划信息，这里注意，这个执行计划里面的信息不是CBO根据表分析数据估算出的数值，而是SQL语句实际执行过程中消耗的资源信息，其中：
Rows 当前操作返回的实际返回的记录数。
Row Source Operation 表示当前操作的数据访问方式。
cr（consistent read）一致性读取的数据块，相当于query列上的fetch的值
pr（physical read）物理读取的数据块，相当于disk列上的fetch的值
pw（physical write） 物理写
time 当前操作执行时间
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID TEST (cr=3 pr=0 pw=0 time=0 us cost=2 size=29 card=1)
1 INDEX UNIQUE SCAN SYS_C00399080 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 217036)
下面部分是对这个sql_trace期间所有非递归sql语句的执行信息汇总
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 3 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
下面是递归调用语句的信息统计，递归sql语句是指执行一条sql语句衍生执行其它的sql，这些衍生出来的sql语句叫做递归sql语句。比如Oracle为了执行我们发出的这条sql语句
select * from test where id=100
需要对这条sql语句进行分析，需要读取一些数据字典来获取相关信息，比如是否有权限，对象是否有存在，对象的存储信息，下面统计都为0是因为这条sql语句之前已经执行过，
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.
上面是一个通过tkprof工具处理后的结果集，它真实的统计了sql在运行过程中的各种资源消耗，这个报告对于分析性能有问题的sql语句非常重要
如果你想确切地知道sql语句的每一步执行时如何操作的，就需要分析原始的trace文件，下面给出了这条sql语句的关键部分
PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1381490108569206 hv=459648918 ad='6d9c7590' sqlid='d3gtqbsdqbbwq'
select * from test where id=100
END OF STMT
PARSE #1:c=1999,e=1757,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4274779609,tim=1381490108569205
EXEC #1:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4274779609,tim=1381490108569319
FETCH #1:c=0,e=92,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=4274779609,tim=1381490108569461
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=217035 op='TABLE ACCESS BY INDEX ROWID TEST (cr=3 pr=0 pw=0 time=0 us cost=2 size=29 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=217036 op='INDEX UNIQUE SCAN SYS_C00399080 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4274779609,tim=1381490108591269
..........
我们看到Oracle首先对这条sql语句做分析，并且有一个游标号CURSOR #1，这个在整个trace文件中不是唯一的，当一条sql语句执行完毕后，这个号会被另外一个sql语句重用
我们还可以看到这条sql语句被分析了一次，执行了一次，fetch了2次，stat#1是对这条sql语句执行过程中的资源消耗的统计，这些输出顺序就是sql语句的执行顺序，通过这些顺序就可以了解到sql语句是如何一步一步执行的。
下面是列出了这些指标的解释
PARSING IN CURSOR 部分
len：被分析sql的长度
dep：产生递归sql的深度
uid：user id
otc：Oracle command type命令的类型
lid：私有用的id
tim：时间戳
hv： hash value
ad： sql address
PARSE，EXEC，FETCH部分：
c: 消耗的cpu time
e：elapsed time 操作的用时
p：physical reads次数
cr：consistent reads数据的块
cu：current方式读取的数据块
mis：cursor miss in canche硬分析次数
r：rows处理的行数
dep：depth递归sql的深度
og：optimize goal优化器模式
tim：timstamp时间戳
stats部分：
id：执行计划的行源号
cnt：当前行源返回的行数
pid：当前行源的父号
pos：执行计划中的位置
obj：当前操作的对象id
op：当前行源的数据访问操作
三 10046事件
10046事件按照收集信息的内容，可以分为4个级别
1）Level 1 等同于sql_trace的功能。
2）Level 4 在Level 1的基础上收集绑定变量的信息
3）level 8 在Level 1的基础上增加了等等事件的信息
4）level12 等同于Level 4 + Level *，集同时收集绑定变量和等待事件信息
可以看出level级别越高，收集的信息越全面，我们用下面例子来分别看下这几个级别的作用
（1）LEVEL 4
--首先查询trace文件路径
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_9493.trc
SQL> create table test as select * from dba_objects;
Table created.
SQL> exec dbms_stats.gather_table_stats('sys','test');
PL/SQL procedure successfully completed.
--设定10046事件的级别为4
SQL> alter session set events '10046 trace name context forever,level 4';
Session altered.
--定义2个变量x，y
SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
PL/SQL procedure successfully completed.
SQL> exec :y :='TEST';
PL/SQL procedure successfully completed.
--通过绑定变量查询表
SQL> select object_id,object_name from test where object_id=:x or object_name=:y;
OBJECT_ID OBJECT_NAM
---------- ----------
20 ICOL$
221329 TEST
SQL> alter session set events '10046 trace name context off';
Session altered.
这样就完成了使用10046事件做SQL trace的工作，注意，LEVEL 4获取的绑定变量的信息只能在原始的trace文件里面获取，在通过tkprof工具格式化后是看不到的，下面是这条sql在原始文件中的关键部分
=====================
PARSING IN CURSOR #1 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381546195913578 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #1:c=0,e=99,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381546195913577
BINDS #1:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=7fb340f24728 bln=22 avl=02 flg=05
value=20
Bind#1
oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=7fb340f24740 bln=32 avl=04 flg=01
value="TEST"
EXEC #1:c=0,e=139,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381546195913782
FETCH #1:c=0,e=128,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381546195913961
FETCH #1:c=10999,e=11326,p=0,cr=1052,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381546195925477
STAT #1 id=1 cnt=2 pid=0 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=90 card=3)'
我们清楚的看到CURSOR #1 运行了绑定变量BINDS #1:
Bind#0 表示第一个绑定变量，最后一个value=20，表示这个变量的值为20
Bind#1 表示第二个绑定变量，最后一个value="TEST"，表示这个变量的值为TEST
2) LEVEL 8
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_9603.trc
--打开另外一个session 2 模拟TX - row lock contention等待事件
SQL> update test set object_id=10 where object_name='TEST';
1 row updated.
--回到这个session启用10046 level 8
SQL> alter session set events '10046 trace name context forever,level 8';
Session altered.
--更新同一行，这个时候session就被另外一个session阻塞了
SQL> update test set object_id=20 where object_name='TEST';
--等待1分钟后，在session 2 commit
SQL> commit;
Commit complete.
--回到session 通过绑定变量做查询
SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
PL/SQL procedure successfully completed.
SQL> exec :y :='TEST';
PL/SQL procedure successfully completed.
SQL> col object_name for a10;
SQL> select object_id,object_name from test where object_id=:x or object_name=:y;
OBJECT_ID OBJECT_NAM
---------- ----------
20 ICOL$
20 TEST
SQL> alter session set events '10046 trace name context off';
Session altered.
下面是等待事件相关的类容
PARSING IN CURSOR #1 len=53 dep=0 uid=0 oct=6 lid=0 tim=1381547023329562 hv=902883731 ad='763c0908' sqlid='fm3f2m0ux1ucm'
update test set object_id=20 where object_name='TEST'
END OF STMT
PARSE #1:c=2000,e=2079,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=839355234,tim=1381547023329561
*** 2013-10-12 11:04:37.870
WAIT
#1: nam='enq: TX - row lock contention' ela= 54462429
name|mode=1415053318 usn<<16 | slot=65562 sequence=9055
obj#=221329 tim=1381547077870603
EXEC #1:c=10997,e=54541351,p=0,cr=1057,cu=4,mis=0,r=1,dep=0,og=1,plh=839355234,tim=1381547077870989
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE TEST (cr=1057 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=60 card=2)'
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381547077871119
*** 2013-10-12 11:05:14.205
WAIT #1: nam='SQL*Net message from client' ela= 36334185 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381547114205328
CLOSE #1:c=0,e=16,dep=0,type=0,tim=1381547114206287
可以清楚的看到在CURSOR #1有刚才模拟的等待事件enq: TX - row lock contention
下面是select的相关内容
PARSING IN CURSOR #6 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381548130797812 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #6:c=0,e=299,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1381548130797811
EXEC #6:c=1000,e=751,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1357081020,tim=1381548130798637
WAIT #6: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130798688
FETCH #6:c=0,e=48,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381548130798766
WAIT #6: nam='SQL*Net message from client' ela= 180 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130798986
WAIT #6: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130807489
FETCH #6:c=8999,e=8627,p=0,cr=1052,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381548130807646
STAT #6 id=1 cnt=2 pid=0 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=90 card=3)'
可以看出LEVEL 8 里面没有包含绑定变量的信息
3) LEVEL 12
操作步骤和LEVEL 8 一样
下面是等待事件信息
PARSING IN CURSOR #1 len=53 dep=0 uid=0 oct=6 lid=0 tim=1381548626071590 hv=3865385185 ad='7011bc50' sqlid='a30698vm6a671'
update test set object_id=10 where object_name='TEST'
END OF STMT
PARSE #1:c=0,e=1147,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=839355234,tim=1381548626071589
*** 2013-10-12 11:30:46.006
WAIT
#1: nam='enq: TX - row lock contention' ela= 19930521
name|mode=1415053318 usn<<16 | slot=131092 sequence=12176
obj#=221329 tim=1381548646006494
EXEC #1:c=4999,e=19935098,p=0,cr=1057,cu=4,mis=0,r=1,dep=0,og=1,plh=839355234,tim=1381548646006763
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE TEST (cr=1057 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=60 card=2)'
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381548646006926
*** 2013-10-12 11:30:49.893
WAIT #1: nam='SQL*Net message from client' ela= 3886351 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381548649893302
下面是绑定变量信息
PARSING IN CURSOR #1 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381548682580601 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381548682580599
BINDS #1:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=7f1296db5758 bln=22 avl=02 flg=05
value=20
Bind#1
oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=7f1296db5770 bln=32 avl=04 flg=01
value="TEST"
EXEC #1:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381548682580809
可以看出LEVEL 14 = LEVEL 4 + LEVEL 8
如同SQL_TRACE如果跟踪其它session，同样在获取session的sid和serial后即可通过下面的命令跟踪
SQL> exec dbms_monitor.session_trace_enable(100,11110,waits=>true,bind=>true); --启用
SQL> exec dbms_monitor.session_trace_disable(100,11110); --禁用
另外启用10046事件受下面两个参数的影响
SQL> show parameter timed_statistics
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
timed_statistics boolean TRUE
SQL> show parameter max_dump_file_size;
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
max_dump_file_size string unlimited
在oracle 10g后在两个参数保存默认就好了，简单知道就可以了。
转载：http://5073392.blog.51cto.com/5063392/1308195
一，SQL_TRACE： SQL_TRACE命令会将执行的整个过程输出到一个trace文件，我通过阅读这个trace文件来了解这个sql在执行过程中Oracle究竟做了哪些事情
1）确定trace文件的路径
启用sql_trace前我们首先要确定跟踪文件的存放位置，即user_dump_dest下
SQL> show parameter user_dump_dest;
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /u01/opt/oracle/admin/orcl
/udump
sql trace文件固定格式为<user_dump_dest>/<instance_name>_ora_<backgroudProcessID>.trc
其中user_dump_dest,instance_name的值可以通过show命令得到，backgroudProcessID的值就需要首先获取session的sid然后根据sid的值查询v$session中进程的地址，然后根据进程地址找到processID，在11G以前可以通过下面这个语句获取当前session的sql_trace文件的路径
SQL> select
a.value || '/' || b.instance_name || '_ora_' || c.spid || '.trc' trace_file
from
(select value from v$parameter where name= 'user_dump_dest') a,
(select instance_name from v$instance) b,
(select spid from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat))) c;
TRACE_FILE
--------------------------------------------------------------------------------
/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810.trc
在11g以后v$process视图里面tracefile 字段直接给出了这个值，因此不需要写上面那么麻烦的语句
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_29991.trc
另外也可以手工更改产生trace文件的名称例如
SQL> alter session set tracefile_identifier='mytrace'
执行这条语句后就会在原有的tracename上加上_mytrace例如前面查出来的/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810.trc就会变成/u01/opt/oracle/admin/orcl/udump/orcl_ora_7810_mytrace.trc这时我们只需要到user_dump_dest的路径下通过ls命令匹配关键字mytrace就可以了，就没有必要去写sql查询了。
2）启用sql_trace
启用sql_trace可以通过从instance级别和session级别，我们知道每个session都会有一个trace文件，因此在实例级别启用如果session越多将暂用的系统资源越多，除非有特殊的需求。
下面的语句可以启用实例级别的trace
SQL> alter system set sql_trace=true
SQL> show parameter sql_trace
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
sql_trace boolean TURE
从session级别启动有两种方式，第一跟踪当前的session，第二跟踪其它的session，我们只需要确定备跟踪会话的sid和serial#的值就可以了
当前session：
SQL> alter system set sql_trace=ture;
其它session：
例如确定了session id=138然后查询v$session获取serial#
SQL> select sid,serial# from v$session where sid=138;
SID SERIAL#
---------- ----------
138 2397
然后执行下面的包来跟踪这个session
SQL> execute dmbs_system.set_sql_trace_in_session(138,2397,true)
停止：
SQL> execute dmbs_system.set_sql_trace_in_session(138,2397,false)
二，TKPROF工具
默认生成的trace文件的可读性是比较差的，我们通常会用TKPROF这个工具来格式化在个trace文件。tkprof工具是oracle自带的一个工具，用于处理原始的trace文件，它的主要作用是合并汇总trace文件中的一些项，规范化文件格式，使得文件具有可读性，下面是简单的格式化一个文件
[oracle@localhost trace]$ tkprof RBKSAFARI_ora_1302.trc new.txt
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:08:57 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
-----------------------------------------------------
下面来执行一条sql语句使用，看看trace文件中的内容信息
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_30598.trc
SQL> alter session set sql_trace=true;
Session altered.
SQL> select * from test where id=100;
使用tkprof工具格式化RBKSAFARI_ora_30598.trc这个文件
[oracle@localhost trace]$ tkprof RBKSAFARI_ora_30598.trc mytrace.txt
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:17:25 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
用vi打开如下
TKPROF: Release 11.2.0.1.0 - Development on Fri Oct 11 19:17:25 2013
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: RBKSAFARI_ora_30598.trc
Sort options: default
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
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
********************************************************************************
trace文件头部的信息描述了tkprof的版本，以及报告中一些列的定义，在下面的报告中，每一条sql都包含了这条sql执行过程的所有信息，对于任何一条sql都应该包含3个步骤（对应下表的call列）
分析（parse）：SQL的分析阶段
执行（execute）：SQL的执行阶段
数据提取（Fetch）：数据提取阶段
横向的列除了call之外，还包含了一下信息：
count：计算器，表示当前的操作被执行了多少次。
cpu：当前的操作消耗的cpu时间（单位秒）
Elapsed: 当前的操作一共用时多少（包括cpu事件和等待时间）
Disk：当前操作的物理读（磁盘i/o次数）
Query：当前操作的一致性读方式读取的数据块数（通常是查询）
Current：当前操作的current的方式读取的数据库数（通常是修改数据块使用的方式）
Rows：当前操作处理的数据记录数
SQL ID: 4tk6t8tfsfqbf
Plan Hash: 0
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 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 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************
下面才是我们需要的信息，我们执行的那条查询sql的trace信息
SQL ID: d3gtqbsdqbbwq
Plan Hash: 4274779609
select *
from
test where id=100
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.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 3 0 1
我们看到，这条sql语句被分析了一次，执行了一次，数据提取了2次，cpu和elpased都为0是因为这个表暂用的数据比较少，可以看到一共查询3个块，没有物理读，说明这个3个块已经缓冲到了buffer cache中，最后返回了1行的记录
Misses in library cache during parse: 1 --说明在shared pool中没有命中，说明这是一次硬分析
Optimizer mode: ALL_ROWS --当前优化器模式为CBO ALL_ROS
Parsing user id: SYS --分析用户id
下面是这条sql语句的具体执行计划信息，这里注意，这个执行计划里面的信息不是CBO根据表分析数据估算出的数值，而是SQL语句实际执行过程中消耗的资源信息，其中：
Rows 当前操作返回的实际返回的记录数。
Row Source Operation 表示当前操作的数据访问方式。
cr（consistent read）一致性读取的数据块，相当于query列上的fetch的值
pr（physical read）物理读取的数据块，相当于disk列上的fetch的值
pw（physical write） 物理写
time 当前操作执行时间
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID TEST (cr=3 pr=0 pw=0 time=0 us cost=2 size=29 card=1)
1 INDEX UNIQUE SCAN SYS_C00399080 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)(object id 217036)
下面部分是对这个sql_trace期间所有非递归sql语句的执行信息汇总
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 3 0 1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
下面是递归调用语句的信息统计，递归sql语句是指执行一条sql语句衍生执行其它的sql，这些衍生出来的sql语句叫做递归sql语句。比如Oracle为了执行我们发出的这条sql语句
select * from test where id=100
需要对这条sql语句进行分析，需要读取一些数据字典来获取相关信息，比如是否有权限，对象是否有存在，对象的存储信息，下面统计都为0是因为这条sql语句之前已经执行过，
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.
上面是一个通过tkprof工具处理后的结果集，它真实的统计了sql在运行过程中的各种资源消耗，这个报告对于分析性能有问题的sql语句非常重要
如果你想确切地知道sql语句的每一步执行时如何操作的，就需要分析原始的trace文件，下面给出了这条sql语句的关键部分
PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1381490108569206 hv=459648918 ad='6d9c7590' sqlid='d3gtqbsdqbbwq'
select * from test where id=100
END OF STMT
PARSE #1:c=1999,e=1757,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4274779609,tim=1381490108569205
EXEC #1:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4274779609,tim=1381490108569319
FETCH #1:c=0,e=92,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=4274779609,tim=1381490108569461
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=217035 op='TABLE ACCESS BY INDEX ROWID TEST (cr=3 pr=0 pw=0 time=0 us cost=2 size=29 card=1)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=217036 op='INDEX UNIQUE SCAN SYS_C00399080 (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'
FETCH #1:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4274779609,tim=1381490108591269
..........
我们看到Oracle首先对这条sql语句做分析，并且有一个游标号CURSOR #1，这个在整个trace文件中不是唯一的，当一条sql语句执行完毕后，这个号会被另外一个sql语句重用
我们还可以看到这条sql语句被分析了一次，执行了一次，fetch了2次，stat#1是对这条sql语句执行过程中的资源消耗的统计，这些输出顺序就是sql语句的执行顺序，通过这些顺序就可以了解到sql语句是如何一步一步执行的。
下面是列出了这些指标的解释
PARSING IN CURSOR 部分
len：被分析sql的长度
dep：产生递归sql的深度
uid：user id
otc：Oracle command type命令的类型
lid：私有用的id
tim：时间戳
hv： hash value
ad： sql address
PARSE，EXEC，FETCH部分：
c: 消耗的cpu time
e：elapsed time 操作的用时
p：physical reads次数
cr：consistent reads数据的块
cu：current方式读取的数据块
mis：cursor miss in canche硬分析次数
r：rows处理的行数
dep：depth递归sql的深度
og：optimize goal优化器模式
tim：timstamp时间戳
stats部分：
id：执行计划的行源号
cnt：当前行源返回的行数
pid：当前行源的父号
pos：执行计划中的位置
obj：当前操作的对象id
op：当前行源的数据访问操作
三 10046事件
10046事件按照收集信息的内容，可以分为4个级别
1）Level 1 等同于sql_trace的功能。
2）Level 4 在Level 1的基础上收集绑定变量的信息
3）level 8 在Level 1的基础上增加了等等事件的信息
4）level12 等同于Level 4 + Level *，集同时收集绑定变量和等待事件信息
可以看出level级别越高，收集的信息越全面，我们用下面例子来分别看下这几个级别的作用
（1）LEVEL 4
--首先查询trace文件路径
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_9493.trc
SQL> create table test as select * from dba_objects;
Table created.
SQL> exec dbms_stats.gather_table_stats('sys','test');
PL/SQL procedure successfully completed.
--设定10046事件的级别为4
SQL> alter session set events '10046 trace name context forever,level 4';
Session altered.
--定义2个变量x，y
SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
PL/SQL procedure successfully completed.
SQL> exec :y :='TEST';
PL/SQL procedure successfully completed.
--通过绑定变量查询表
SQL> select object_id,object_name from test where object_id=:x or object_name=:y;
OBJECT_ID OBJECT_NAM
---------- ----------
20 ICOL$
221329 TEST
SQL> alter session set events '10046 trace name context off';
Session altered.
这样就完成了使用10046事件做SQL trace的工作，注意，LEVEL 4获取的绑定变量的信息只能在原始的trace文件里面获取，在通过tkprof工具格式化后是看不到的，下面是这条sql在原始文件中的关键部分
=====================
PARSING IN CURSOR #1 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381546195913578 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #1:c=0,e=99,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381546195913577
BINDS #1:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=7fb340f24728 bln=22 avl=02 flg=05
value=20
Bind#1
oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=7fb340f24740 bln=32 avl=04 flg=01
value="TEST"
EXEC #1:c=0,e=139,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381546195913782
FETCH #1:c=0,e=128,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381546195913961
FETCH #1:c=10999,e=11326,p=0,cr=1052,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381546195925477
STAT #1 id=1 cnt=2 pid=0 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=90 card=3)'
我们清楚的看到CURSOR #1 运行了绑定变量BINDS #1:
Bind#0 表示第一个绑定变量，最后一个value=20，表示这个变量的值为20
Bind#1 表示第二个绑定变量，最后一个value="TEST"，表示这个变量的值为TEST
2) LEVEL 8
SQL> select tracefile from v$process where addr=(select paddr from v$session where sid=(select distinct sid from v$mystat));
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/rbksafari/RBKSAFARI/trace/RBKSAFARI_ora_9603.trc
--打开另外一个session 2 模拟TX - row lock contention等待事件
SQL> update test set object_id=10 where object_name='TEST';
1 row updated.
--回到这个session启用10046 level 8
SQL> alter session set events '10046 trace name context forever,level 8';
Session altered.
--更新同一行，这个时候session就被另外一个session阻塞了
SQL> update test set object_id=20 where object_name='TEST';
--等待1分钟后，在session 2 commit
SQL> commit;
Commit complete.
--回到session 通过绑定变量做查询
SQL> var x number;
SQL> var y varchar2(10);
SQL> exec :x := 20;
PL/SQL procedure successfully completed.
SQL> exec :y :='TEST';
PL/SQL procedure successfully completed.
SQL> col object_name for a10;
SQL> select object_id,object_name from test where object_id=:x or object_name=:y;
OBJECT_ID OBJECT_NAM
---------- ----------
20 ICOL$
20 TEST
SQL> alter session set events '10046 trace name context off';
Session altered.
下面是等待事件相关的类容
PARSING IN CURSOR #1 len=53 dep=0 uid=0 oct=6 lid=0 tim=1381547023329562 hv=902883731 ad='763c0908' sqlid='fm3f2m0ux1ucm'
update test set object_id=20 where object_name='TEST'
END OF STMT
PARSE #1:c=2000,e=2079,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=839355234,tim=1381547023329561
*** 2013-10-12 11:04:37.870
WAIT
#1: nam='enq: TX - row lock contention' ela= 54462429
name|mode=1415053318 usn<<16 | slot=65562 sequence=9055
obj#=221329 tim=1381547077870603
EXEC #1:c=10997,e=54541351,p=0,cr=1057,cu=4,mis=0,r=1,dep=0,og=1,plh=839355234,tim=1381547077870989
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE TEST (cr=1057 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=60 card=2)'
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381547077871119
*** 2013-10-12 11:05:14.205
WAIT #1: nam='SQL*Net message from client' ela= 36334185 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381547114205328
CLOSE #1:c=0,e=16,dep=0,type=0,tim=1381547114206287
可以清楚的看到在CURSOR #1有刚才模拟的等待事件enq: TX - row lock contention
下面是select的相关内容
PARSING IN CURSOR #6 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381548130797812 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #6:c=0,e=299,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1381548130797811
EXEC #6:c=1000,e=751,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1357081020,tim=1381548130798637
WAIT #6: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130798688
FETCH #6:c=0,e=48,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381548130798766
WAIT #6: nam='SQL*Net message from client' ela= 180 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130798986
WAIT #6: nam='SQL*Net message to client' ela= 8 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1381548130807489
FETCH #6:c=8999,e=8627,p=0,cr=1052,cu=0,mis=0,r=1,dep=0,og=1,plh=1357081020,tim=1381548130807646
STAT #6 id=1 cnt=2 pid=0 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=90 card=3)'
可以看出LEVEL 8 里面没有包含绑定变量的信息
3) LEVEL 12
操作步骤和LEVEL 8 一样
下面是等待事件信息
PARSING IN CURSOR #1 len=53 dep=0 uid=0 oct=6 lid=0 tim=1381548626071590 hv=3865385185 ad='7011bc50' sqlid='a30698vm6a671'
update test set object_id=10 where object_name='TEST'
END OF STMT
PARSE #1:c=0,e=1147,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=839355234,tim=1381548626071589
*** 2013-10-12 11:30:46.006
WAIT
#1: nam='enq: TX - row lock contention' ela= 19930521
name|mode=1415053318 usn<<16 | slot=131092 sequence=12176
obj#=221329 tim=1381548646006494
EXEC #1:c=4999,e=19935098,p=0,cr=1057,cu=4,mis=0,r=1,dep=0,og=1,plh=839355234,tim=1381548646006763
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE TEST (cr=1057 pr=0 pw=0 time=0 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=221329 op='TABLE ACCESS FULL TEST (cr=1056 pr=0 pw=0 time=0 us cost=287 size=60 card=2)'
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381548646006926
*** 2013-10-12 11:30:49.893
WAIT #1: nam='SQL*Net message from client' ela= 3886351 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1381548649893302
下面是绑定变量信息
PARSING IN CURSOR #1 len=75 dep=0 uid=0 oct=3 lid=0 tim=1381548682580601 hv=2021462068 ad='74fc6200' sqlid='gkkf6ndw7u41n'
select object_id,object_name from test where object_id=:x or object_name=:y
END OF STMT
PARSE #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381548682580599
BINDS #1:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=00 csi=00 siz=56 off=0
kxsbbbfp=7f1296db5758 bln=22 avl=02 flg=05
value=20
Bind#1
oacdty=01 mxl=32(30) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=24
kxsbbbfp=7f1296db5770 bln=32 avl=04 flg=01
value="TEST"
EXEC #1:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=1381548682580809
可以看出LEVEL 14 = LEVEL 4 + LEVEL 8
如同SQL_TRACE如果跟踪其它session，同样在获取session的sid和serial后即可通过下面的命令跟踪
SQL> exec dbms_monitor.session_trace_enable(100,11110,waits=>true,bind=>true); --启用
SQL> exec dbms_monitor.session_trace_disable(100,11110); --禁用
另外启用10046事件受下面两个参数的影响
SQL> show parameter timed_statistics
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
timed_statistics boolean TRUE
SQL> show parameter max_dump_file_size;
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
max_dump_file_size string unlimited
在oracle 10g后在两个参数保存默认就好了，简单知道就可以了。
转载：http://5073392.blog.51cto.com/5063392/1308195
内容来自用户分享和网络整理，不保证内容的准确性，如有侵权内容，可联系管理员处理 
相关文章推荐
- SQL_TRACE和10046事件详解
- SQL_TRACE和10046事件
- Sql_trace及10046事件
- 演示使用sql_trace和10046事件对其他会话进行跟踪，并给出trace结果
- oracle SQL_TRACE和10046事件
- Oracle SQL Trace 和 10046 事件
- 10046事件 sql_trace 启动和停止
- Oracle SQL Trace 和 10046 事件 .
- 演示使用sql_trace和10046事件对其他会话进行跟踪，并给出trace结果
- 10046事件和sql_trace
- 10046事件sql_trace跟踪
- Oracle SQL Trace 和 10046 事件
- SQL Tuning 基础概述03 - 使用sql_trace和10046事件跟踪执行计划
- Oracle SQL Trace 和 10046 事件
- Oracle SQL_TRACE和10046事件优化SQL实例
- Oracle SQL Trace 和 10046 事件跟踪
- Oracle sql_trace 10046事件 10053事件笔记
- Oracle SQL Trace 和 10046 事件跟踪
- 深入理解Oracle调试事件：10046事件详解
- 拜年+散分贴《Oracle SQL_TRACE和10046事件优化SQL实例》