经典10046剖析案例-4

Posted 2020-09-30 Mr.Oracle

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文件中的一些项，规范化文件格式，使得文件具有可读性，下面是简单的格式化一个文件

[[email protected] 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这个文件

[[email protected] 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后在两个参数保存默认就好了，简单知道就可以了。