您在这里：首页 > 学员专区 > 技术文章

Oracle SQL_TRACE和10046事件优化SQL实例

一数据库版本

LEO1@LEO1>select * from v$version;

BANNER

--------------------------------------------------------------------------------

Oracle Database11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

PL/SQL Release11.2.0.1.0 - Production

CORE 11.2.0.1.0 Production

TNS for Linux:Version 11.2.0.1.0 - Production

NLSRTL Version11.2.0.1.0 - Production

二演示使用SQL_TRACE和10046事件对其它会话进行跟踪，并给出trace结果

SQL_TRACE：Oracle这个功能主要是为了追踪SQL的执行过程，分析SQL的性能，资源消耗情况。

1.查看SQL是如何操作处理数据

2.查看SQL在执行过程中产生了的等待事件

3.查看SQL的执行过程资源消耗

4.查看SQL的实际执行计划

5.查看SQL的递归语句

6.如果要探索SQL如何执行的可以详细看看

10046：用于分析SQL执行过程中性能消耗情况，可以查看绑定变量信息，可以查看等待事件信息，它比SQL_TRACE输入输出更多参数。

上述工具使用场合：1.优化SQL语句

2.查看SQL语句执行计划

3.跟踪SQL语句执行过程

4.把会话中SQL的信息重定向到一个文件里

SET AUTO TRACE：1.输出SQL语句估算的执行计划（猜出来的）

2.SQL语句并没有真正执行，只关注这条SQL的执行计划对不对

3.只是用来估算执行计划

实验

使用SQL_TRACE对其它会话进行跟踪

如果对当前会话进行跟踪只需alter session set sql_trace=true;即可，如果对其它会话进行跟踪还需要设置另外一些参数。

我们现在做一下，从144会话跟踪12会话的SQL

144会话我们使用leo1用户操作

12会话我们使用leo2用户操作

144会话

LEO1@LEO1> selectdistinct sid from v$mystat; 可以查询当前会话ID

SID

----------------

144

我们用会话ID和串号来唯一定位一个会话，现在我们把2个会话信息都显示出来了

LEO1@LEO1>select sid,serial# from v$session where sid in (144,12);

SID SERIAL#

---------------------------------

12 4472

144 979

这时我有了一个疑问，定位一个会话一般来说看sid就可以了，那么为什么后面还跟着个serial呢，这个serial是干什么用的呢，咨询了一下Alantany查了一下官方文档

SID NUMBER：Sessionidentifier 就是会话标识

SERIAL# NUMBER ：是用来标识唯一一个会话操作对象的，保证这个会话发出的命令可以正确的应用到对应的会话对象上。

场合一个会话的结束和另一个会话开始都使用了同一个SID，区分这是2个不同的会话

例子

第一次leonarding登陆sid=12，操作了leo1表，退出

SID SERIAL#

---------------------------------

12 4472

第二次Alan登陆sid=12，又操作了leo2表，退出

SID SERIAL#

---------------------------- ----

12 4777

如果只是看SID我们不能分辨出是谁登录了会话操作了leo1表和leo2表，而serial可以分辨出不同会话的命令正确应用到对应的对象上，区分这是2个不同的人登录的会话。

LEO1@LEO1> droptable leo1; 清理环境

Table dropped.

LEO1@LEO1>create table leo1 as select * from dba_objects; 用leo1用户创建leo1表

Table created.

LEO1@LEO1>select count(*) from leo1; 看看有多少条记录

COUNT(*)

----------------

72007

LEO1@LEO1>execute dbms_stats.gather_table_stats('LEO1','LEO1',method_opt=>'for allcolumns size 254');

PL/SQL proceduresuccessfully completed.

随便做个表分析和直方图

LEO1@LEO1> conn/ as sysdba 切换为管理员

Connected.

SYS@LEO1> grantexecute on dbms_system to leo1;授予执行“系统包”的用户权限给leo1，必须授予否则报错

ERROR atline 1:

ORA-06550:line 1, column 7:

PLS-00201:identifier 'DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION' must be declared

ORA-06550:line 1, column 7:

PL/SQL:Statement ignored

SYS@LEO1> connleo1/leo1 我们在切换回来

LEO1@LEO1>execute sys.dbms_system.set_sql_trace_in_session(12,4472,true);

PL/SQL proceduresuccessfully completed.

启动跟踪会话ID=12，SERIAL=4472的SQL

声明：这个存储过程是SYS用户特有的，所以在引用时必须带schema，不带就会报错如下

ERROR atline 1:

ORA-06550:line 1, column 7:

PLS-00201:identifier 'SYS.DBMS_SYSTEM' must be declared

ORA-06550:line 1, column 7:

PL/SQL:Statement ignored

12会话

LEO2@LEO1> select /*+ trace_by_leo1_session*/ count(*) from leo1.leo1; leo2用户查询leo1表

COUNT(*)

----------------

72007 这是执行了第一条语句

/*+trace_by_leo1_session */ 用来标识这条SQL语句是leo2用户发出的，查询的是leo1用户的表

select /*+trace_by_leo1_session */ count(*) from leo1.leo1 这是执行了第二条语句

select /*+trace_by_leo1_session */ object_type,count(*) from leo1.leo1 group byobject_type

这是执行了第三条语句

我们从trace文件里面找一找追踪到这三条语句了嘛

144会话

LEO1@LEO1>execute sys.dbms_system.set_sql_trace_in_session(12,4472,false);

PL/SQL proceduresuccessfully completed.

关闭跟踪会话ID=12，SERIAL=4472的SQL（exit sqlplus也可以达到同样效果）

LEO1@LEO1>select * from v$diag_info where name like 'Default Trace File';

INST_ID NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

1 Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_8420.trc

指定当前会话写入的trace文件，这里面就记载了我刚才追踪的12会话上执行的SQL信息

如果你用的是Oracle 10g则目录不同请注意

[oracle@leonarding1~]$ cd /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/

[oracle@leonarding1trace]$ ll | grep LEO1_ora_8420.trc

显示没有这个文件，退出试试

LEO1@LEO1> exit

Disconnected fromOracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

With thePartitioning, OLAP, Data Mining and Real Application Testing options

还是没有，后来我根据执行时间猜出是LEO1_ora_7455.trc这个文件，不知道是怎么回事

[oracle@leonarding1trace]$ vim LEO1_ora_7455.trc 我们阅读一下原始trace文件

=======================================================================================

PARSING IN CURSOR#4 len=59 dep=0 uid=86 ct=3 lid=86 tim=1360332670938439 hv=3157118559ad='7d950658' sqlid='42nypzay2vmkz'

select/*+ trace_by_leo1_session */ count(*) from leo1.leo1 第一条语句，有1次硬解析

END OF STMT

PARSE#4:c=5000,e=28805,p=0,cr=6,cu=0,mis=1,r=0,dep=0,og=1,plh=4191104944,tim=1360332670938434

EXEC#4:c=0,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4191104944,tim=1360332670938668

FETCH#4:c=20997,e=21272,p=0,cr=1031,cu=0,mis=0,r=1,dep=0,og=1,plh=4191104944,tim=1360332670960096

STAT #4 id=1 cnt=1pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)'

STAT #4 id=2cnt=72007 pid=1 pos=1 bj=74145 p='TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0 time=623242us cost=288 size=0 card=72007)'

FETCH#4:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4191104944,tim=1360332670960834

*** 2013-02-0822:12:08.997

CLOSE#4:c=0,e=44,dep=0,type=0,tim=1360332728997966

使用的是4号游标，PARSE #4解析-> EXEC #4执行-> FETCH #4 取操作-> CLOSE #4关闭游标

=======================================================================================

PARSING IN CURSOR#2 len=59 dep=0 uid=86 ct=3 lid=86 tim=1360330870718759 hv=3157118559 ad='7d950658'sqlid='42nypzay2vmkz'

select/*+ trace_by_leo1_session */ count(*) from leo1.leo1 第二条语句，还有1次硬解析

END OF STMT

PARSE#2:c=3000,e=2516,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4191104944,tim=1360330870718752

EXEC#2:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4191104944,tim=1360330870719008

FETCH#2:c=19997,e=20021,p=0,cr=1031,cu=0,mis=0,r=1,dep=0,og=1,plh=4191104944,tim=1360330870739148

STAT #2 id=1 cnt=1pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)'

STAT #2 id=2cnt=72007 pid=1 pos=1 bj=74145 p='TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0time=477183 us cost=288 size=0 card=72007)'

FETCH#2:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=4191104944,tim=1360330870739918

CLOSE#7:c=0,e=37,dep=0,type=0,tim=1360332670909360

使用的是2号游标，PARSE #2解析-> EXEC #2执行-> FETCH #2 取操作

=======================================================================================

PARSING IN CURSOR#3 len=92 dep=0 uid=86 ct=3 lid=86 tim=1360332728999761 hv=1179742142ad='7f52a418' sqlid='afbr2j5352vxy'

select/*+ trace_by_leo1_session */ object_type,count(*) from leo1.leo1 group byobject_type

第三条语句

END OF STMT

PARSE#3:c=1000,e=1664,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=908401892,tim=1360332728999755

EXEC#3:c=0,e=102,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=908401892,tim=1360332728999981

FETCH#3:c=38994,e=38233,p=0,cr=1031,cu=0,mis=0,r=1,dep=0,og=1,plh=908401892,tim=1360332729038339

FETCH#3:c=0,e=203,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=908401892,tim=1360332729039339

FETCH#3:c=0,e=177,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=908401892,tim=1360332729040527

FETCH#3:c=0,e=236,p=0,cr=0,cu=0,mis=0,r=12,dep=0,og=1,plh=908401892,tim=1360332729041957

STAT #3 id=1cnt=43 pid=0 pos=1 bj=0 p='HASH GROUP BY (cr=1031 pr=0 pw=0 time=0 uscost=290 size=387 card=43)'

STAT #3 id=2cnt=72007 pid=1 pos=1 bj=74145 p='TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0time=497135 us cost=288 size=648063 card=72007)'

*** 2013-02-0822:12:21.604

CLOSE #3:c=0,e=34,dep=0,type=0,tim=1360332741604218

使用的是3号游标，PARSE #3解析-> EXEC #3执行-> FETCH #3 取操作-> CLOSE #3关闭游标

每次执行都使用了不同的游标号，由此可见我们顺利的跟踪了12会话SQL

=======================================================================================

这个原始trace文件内容比较多，不是很好看，需要花很多时间来斟酌，如果想详细了解SQL整个执行过程的话可以慢慢研究一下。下面我们来看用tkprof工具汇总的精简版report

[oracle@leonarding1trace]$ tkprof LEO1_ora_7455.trc sql_trace.txt sys=no

TKPROF: Release11.2.0.1.0 - Development on Fri Feb 8 22:50:10 2013

sys=no参数表示过滤掉sys用户生成的递归语句，这样可以精简出比较好看的报告

[oracle@leonarding1trace]$ vim sql_trace.txt

********************************************************************************

SQL ID:42nypzay2vmkz

Plan Hash:4191104944

select/*+ trace_by_leo1_session */ count(*) from leo1.leo1

call count cpu elapsed disk query current rows

------------- -------- ---------- -------------------- ---------- ----------

Parse 2 0.00 0.02 0 0 0 0

Execute 2 0.00 0.00 0 0 0 0

Fetch 4 0.04 0.04 0 2062 0 2

------------- -------- ---------- -------------------- ---------- ----------

total 8 0.04 0.07 0 2062 0 2

Misses in librarycache during parse: 2 硬解析了2次，说明把上面的2条相同SQL汇总成了一份SQL报告，每条SQL都硬解析了1次

Optimizer mode:ALL_ROWS

Parsing user id:86

Rows Row Source Operation

下面是SQL实际的执行计划，也有可能与autotrace不同，可以很方便的进行比对研究

------- ---------------------------------------------------

1 SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)

72007 TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0 time=477183 us cost=288 size=0card=72007)

********************************************************************************

SQL ID:afbr2j5352vxy

Plan Hash:908401892

select/*+ trace_by_leo1_session */ object_type,count(*) from leo1.leo1 group byobject_type

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 4 0.03 0.03 0 1031 0 43

------------- -------- ---------- -------------------- ---------- ----------

total 6 0.03 0.04 0 1031 0 43

Misses in librarycache during parse: 1 这条语句也做了1次硬解析

Optimizer mode:ALL_ROWS

Parsing user id:86

Rows Row Source Operation 这个行源操作，就是SQL实际的执行过程

------- ---------------------------------------------------

43 HASH GROUP BY (cr=1031 pr=0 pw=0 time=0 us cost=290 size=387 card=43)

72007 TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0 time=497135 us cost=288size=648063 card=72007)

********************************************************************************

使用10046事件对其它会话进行跟踪

146会话我们使用leo1用户操作

12会话我们使用leo2用户操作

146会话

LEO1@LEO1> selectdistinct sid from v$mystat;

SID

-----------------

146

查询一下2个会话的ID和SERIAL

LEO1@LEO1>select sid,serial# from v$session where sid in (146,12);

SID SERIAL#

---------------------------- ----

12 4777

146 1035

LEO1@LEO1> droptable leo2; 清理环境

Table dropped.

LEO1@LEO1>create table leo2 as select * from dba_objects;创建leo2来做测试区别上一个实验

Table created.

LEO1@LEO1>execute sys.dbms_system.set_ev(12,4777,10046,12,'LEO2');

12：要跟踪的会话ID

4777：会话串号

10046：事件号

12：level级别

LEO2：跟踪的用户名，当前用户可设置为空

声明：这个存储过程是SYS用户特有的，所以在引用时必须带schema，不带就会报错如下

ERROR atline 1:

ORA-06550:line 1, column 7:

PLS-00201:identifier 'DBMS_SYSTEM.SET_EV' must be declared

ORA-06550:line 1, column 7:

PL/SQL:Statement ignored

12会话

LEO2@LEO1>select /*+ 10046_trace_leo2_session */ count(*) from leo1.leo2;

COUNT(*)

----------

72007

/*+10046_trace_leo2_session */用来标识使用10046事件追踪leo用户的会话，方便在trace文件里找

LEO2@LEO1>select /*+ 10046_trace_leo2_session */ object_type,count(*) from leo1.leo2group by object_type;

OBJECT_TYPE COUNT(*)

-------------------------------------- ----------

EDITION 1

INDEXPARTITION 131

CONSUMERGROUP 25

SEQUENCE 223

TABLEPARTITION 128

SCHEDULE 3

QUEUE 35

RULE 1

JAVA DATA 328

PROCEDURE 160

OPERATOR 55

146会话

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_16565.trc

查询一下当前会话写入的trace文件，是不是还是找不到呢，嗯你猜对了

[oracle@leonarding1trace]$ ll | grep LEO1_ora_16565.trc 就像于谦唱的一无所有

LEO1@LEO1> exit leo1用户退出

Disconnected fromOracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

With thePartitioning, OLAP, Data Mining and Real Application Testing options

LEO2@LEO1> exit leo2用户退出

Disconnected fromOracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

With thePartitioning, OLAP, Data Mining and Real Application Testing options

[oracle@leonarding1trace]$ ll | grep LEO1_ora_16565.trc 肿么还是木有呢，看来还滴猜

我这块的trace文件没有生成，我查询了临近的所有原始文件都没有找到，知道原委的朋友可请教哦有加分滴！

三演示10046 level 1,4,8,12的区别

10046事件不同级别：追踪的信息不同

Level 1：等同于SQL_TRACE

Level 4：在Level1的基础上增加收集绑定变量的信息

Level 8：在Level1的基础上增加等待事件的信息，这个有用，如果一条SQL语句非常非常慢，可以查一下是什么原因导致的如此慢

Level 12：等同于Level 4+Level 8，即同时收集绑定变量信息和等待事件信息

汇总：级别高的概括级别低的

实验

10046 Level 1

这个级别的trace信息和SQL_TRACE中的内容是一致的，我们可以用一个绑定变量SQL来测试一下效果

LEO1@LEO1> setlinesize 300 调整格式

LEO1@LEO1> setpagesize 999

LEO1@LEO1>variable i number; 定义变量

LEO1@LEO1>execute :i:=100; 变量赋值

PL/SQL proceduresuccessfully completed.

LEO1@LEO1>alter session set events '10046 trace name context forever,level 1';

Oracle下所有启动事件的通用格式，级别为1

Session altered.

LEO1@LEO1>select * from leo2 where object_id=:i; 绑定变量，重用SQL执行计划

OWNER OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_IDOBJECT_TYPE CREATED LAST_DDL_ TIMESTAMP STATUS T G S

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ---------- -------------- ---------------------------- --------- ------------------- ------- - - -

NAMESPACE EDITION_NAME

---------- ------------------------------

SYS ORA$BASE 100 EDITION 15-AUG-09 15-AUG-092009-08-15:00:16:54 VALID N N N

LEO1@LEO1>alter session set events '10046 trace name context off'; 关闭10046事件

Session altered.

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

当前会话写入的trace文件

LEO1@LEO1> !vim/u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc 我们看一下原始trace文件

====================================================================================

PARSING IN CURSOR#2 len=37 dep=0 uid=85 ct=3 lid=85 tim=1360372361916503 hv=21593726ad='7da84c28' sqlid='4z9c6ch0nkzmy'

select *from leo2 where object_id=:i 我们看不到绑定变量值，只能看到它是一个绑定变量

END OF STMT

PARSE #2:c=2999,e=7530,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360372361916485

EXEC#2:c=2999,e=2920,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2258638698,tim=1360372361920321

FETCH#2:c=0,e=458,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=2258638698,tim=1360372361928304

FETCH#2:c=20996,e=22661,p=0,cr=1027,cu=0,mis=0,r=0,dep=0,og=1,plh=2258638698,tim=1360372361953093

STAT #2 id=1 cnt=1pid=0 pos=1 bj=74150 p='TABLE ACCESS FULL LEO2 (cr=1032 pr=0 pw=0 time=0 uscost=288 size=97 card=1)'

*** 2013-02-0909:13:00.053

CLOSE #2:c=0,e=66,dep=0,type=0,tim=1360372380053747

使用的是2号游标，PARSE #2解析-> EXEC #2执行-> FETCH #2 取操作-> CLOSE #2关闭游标

SQL_TRACE和10046事件内容是按时间顺序打印出来的，过程如上所示

mis=1我们进行了一次硬解析

在Level 1下是看不到绑定变量值是多少的，只能看到有存在绑定变量

=====================================================================================

10046 Level 4

在这个级别中我们就可以看到绑定变量信息了

LEO1@LEO1>alter session set events '10046 trace name context forever,level 4'; 我们设置级别为4

Session altered.

LEO1@LEO1>select * from leo2 where object_id=:i; 继续绑定变量

OWNER OBJECT_NAME SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE CREATED LAST_DDL_ TIMESTAMP STATUS T G S

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- ---------- -------------- ------------------- ------------------ ------------------- ------- - - -

NAMESPACE EDITION_NAME

----------------------------------------

SYS ORA$BASE 100 EDITION 15-AUG-09 15-AUG-092009-08-15:00:16:54 VALID N N N

LEO1@LEO1>alter session set events '10046 trace name context off'; 关闭10046事件

Session altered.

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

还是同一个trace文件

LEO1@LEO1> !vim/u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc 打开trace瞧一瞧

=======================================================================================

PARSING IN CURSOR#4 len=37 dep=0 uid=85 ct=3 lid=85 tim=1360373199428632 hv=21593726ad='7da84c28' sqlid='4z9c6ch0nkzmy'

select *from leo2 where object_id=:i

END OF STMT

PARSE#4:c=0,e=254,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2258638698,tim=1360373199428619

BINDS#4: 绑定的是4号游标

Bind#0 0表示绑定的第一个变量如果是1表示绑定的第二个变量，以此类推

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00pre=00

oacflg=03 fl2=1000000 frm=00 csi=00 siz=24off=0

kxsbbbfp=7f2e8344efa0 bln=22 avl=02 flg=05

value=100这就是绑定的变量值

EXEC#4:c=2000,e=31957,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2258638698,tim=1360373199461116

FETCH#4:c=1000,e=730,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,plh=2258638698,tim=1360373199462378

FETCH#4:c=25996,e=26510,p=0,cr=1027,cu=0,mis=0,r=0,dep=0,og=1,plh=2258638698,tim=1360373199491356

STAT #4 id=1 cnt=1pid=0 pos=1 bj=74150 p='TABLE ACCESS FULL LEO2 (cr=1032 pr=0 pw=0 time=0 uscost=288 size=97 card=1)'

*** 2013-02-0909:26:48.104

CLOSE#4:c=0,e=66,dep=0,type=1,tim=1360373208104843

mis=0 由于刚才我们已经硬解析过了，这次直接软解析，即SQL执行计划重用

这次使用的是4号游标，这个游标号是可以重复使用的，级别4就增加了绑定变量信息

=======================================================================================

10046 Level 8

这个级别中，可以显示SQL语句等待事件，我们就可以知道SQL语句是在等待某些资源，还是没有等待资源速度就是这样了，只能提升硬件

LEO1@LEO1>alter session set events '10046 trace name context forever,level 8'; 级别为8

Session altered.

LEO1@LEO1>select count(*) from leo2 where object_id=:i group by object_name;执行SQL

COUNT(*)

----------

LEO1@LEO1>alter session set events '10046 trace name context off'; 关闭10046事件

Session altered.

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

LEO1@LEO1> !vim/u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc 我们定眼观瞧

======================================================================================

PARSING IN CURSOR#4 len=65 dep=0 uid=85 ct=3 lid=85 tim=1360373900654762 hv=3813172666ad='7dbb2f78' sqlid='fr4tufgjnhtdu'

selectcount(*) from leo2 where object_id=:i group by object_name

END OF STMT

PARSE#4:c=1999,e=1923,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1360373900654751

EXEC#4:c=5000,e=5370,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=2474819896,tim=1360373900660419

WAIT #4:nam='SQL*Net message to client'ela= 17 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360373900661831

FETCH #4:c=20997,e=20590,p=0,cr=1031,cu=0,mis=0,r=1,dep=0,og=1,plh=2474819896,tim=1360373900682600

WAIT #4:nam='SQL*Net message from client'ela= 1168 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360373900684127

FETCH#4:c=1000,e=245,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2474819896,tim=1360373900684583

STAT #4 id=1 cnt=1pid=0 pos=1 bj=0 p='HASH GROUP BY (cr=1031 pr=0 pw=0 time=0 us cost=289size=30 card=1)'

STAT #4 id=2 cnt=1pid=1 pos=1 bj=74150 p='TABLE ACCESS FULL LEO2 (cr=1031 pr=0 pw=0 time=0 uscost=288 size=30 card=1)'

WAIT #4:nam='SQL*Net message to client'ela= 14 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360373900685343

*** 2013-02-0909:38:28.482

WAIT #4:nam='SQL*Net message from client' ela= 7797435 driver id=1650815232 #bytes=1p3=0 obj#=-1 tim=1360373908482852

CLOSE#4:c=0,e=90,dep=0,type=0,tim=1360373908483370

这次还是重用4号游标，标红的都是标识SQL语句WAIT等待事件，这几个等待事件都是正常的等待客户端发送命令的事件，说明我们的SQL语句效率都挺高的

======================================================================================

10046 Level 12

这个级别即可以显示绑定变量，又可以显示等待事件

LEO1@LEO1>alter session set events '10046 trace name context forever,level 12'; 现在级别可为12

Session altered.

LEO1@LEO1>select count(*) from leo2 where object_id=:i group by object_name;

COUNT(*)

----------

LEO1@LEO1>alter session set events '10046 trace name context off'; 关闭10046事件

Session altered.

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

LEO1@LEO1> !vim/u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc 我们再次观瞧

==================================================================================

PARSING IN CURSOR#2 len=65 dep=0 uid=85 ct=3 lid=85 tim=1360375064416180 hv=3813172666ad='7dbb2f78' sqlid='fr4tufgjnhtdu'

select count(*)from leo2 where object_id=:i group by object_name

END OF STMT

PARSE#2:c=0,e=266,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2474819896,tim=1360375064416167

BINDS#2: 这是绑定变量的信息

Bind#0 0表示绑定的第一个变量

oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00pre=00

oacflg=03 fl2=1000000 frm=00 csi=00 siz=24off=0

kxsbbbfp=7f2e834ccec8 bln=22 avl=02 flg=05

value=100 变量值

EXEC#2:c=1000,e=639,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2474819896,tim=1360375064417345

WAIT #2:nam='SQL*Net message to client'ela= 18 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360375064417579

FETCH#2:c=18997,e=20107,p=0,cr=1031,cu=0,mis=0,r=1,dep=0,og=1,plh=2474819896,tim=1360375064437826

WAIT #2:nam='SQL*Net message from client'ela= 846 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360375064439398

FETCH#2:c=0,e=127,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2474819896,tim=1360375064439680

STAT #2 id=1 cnt=1pid=0 pos=1 bj=0 p='HASH GROUP BY (cr=1031 pr=0 pw=0 time=0 us cost=289size=30 card=1)'

STAT #2 id=2 cnt=1pid=1 pos=1 bj=74150 p='TABLE ACCESS FULL LEO2 (cr=1031 pr=0 pw=0 time=0 uscost=288 size=30 card=1)'

WAIT #2:nam='SQL*Net message to client'ela= 18 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1360375064440089

又有等待事件的信息，也是我们常用的级别

*** 2013-02-0909:57:52.607

WAIT #2:nam='SQL*Net message from client' ela= 8167539 driver id=1650815232 #bytes=1p3=0 obj#=-1 tim=1360375072607728

CLOSE#2:c=0,e=129,dep=0,type=0,tim=1360375072608199

这次使用的是2号游标，PARSE #2马上EXEC #2执行FETCH #2取操作紧接着输出执行计划

==================================================================================

小结：到此我们完成了1~12级别的对比说明，10046事件是我们非常常用的优化SQL的监控工具，而我们最常用的是级别12，有了这些信息我们就可以游刃有余的分析和改善SQL性能

四自己构造两条完全同样功能的SQL，通过对SQL_TRACE产生的trace文件的分析，比较它们的性能忧劣。

LEO1@LEO1> droptable leo4 purge; 清空环境

Table dropped.

LEO1@LEO1>create table leo4 as select * from dba_objects; 创建leo4表

Table created.

LEO1@LEO1> altersession set sql_trace=true; 启动SQL_TRACE

Session altered.

LEO1@LEO1>select count(*) from leo4; 功能：统计全表总记录数

COUNT(*)

---------------------

71968

LEO1@LEO1>select sum(count_id) from (select count(object_id) count_id from leo4 group byobject_type);

SUM(COUNT_ID) 功能一样但消耗的资源不同，说明了SQL功能性和优化性同等重要

----------------------

71968

LEO1@LEO1>alter session set sql_trace=false; 关闭SQL_TRACE

Session altered.

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

[oracle@leonarding1trace]$ tkprof LEO1_ora_25998.trc 25998_2.txt

TKPROF: Release11.2.0.1.0 - Development on Tue Feb 12 17:38:34 2013

********************************************************************************

SQL ID:7hruqqqzx2zs7

Plan Hash:3210696650

selectcount(*) from leo4

call count cpu elapsed disk query current rows

------------- -------- ---------- -------------------- ---------- ----------

Parse 1 0.00 0.00 0 1 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.03 0.03 722 1030 0 1

------------- -------- ---------- -------------------- ---------- ----------

total 4 0.03 0.03 722 1031 0 1

Misses in librarycache during parse: 1

Optimizer mode:ALL_ROWS

Parsing user id:85

Rows Row Source Operation

------- ---------------------------------------------------

1 SORT AGGREGATE (cr=1030 pr=722 pw=0 time=0 us)

71968 TABLE ACCESS FULL LEO4 (cr=1030 pr=722 pw=0 time=825511 us cost=287size=0 card=77424)

1.有1次硬解析

2.cpu time和elapsed time 0.03

3.行源操作只有2步就可完成

4.cr=1030 一个指标

5.由于是第一次统计，所以产生了pr=722次物理读

***************************************************************************************

SQL ID:9zhvsut63s579

Plan Hash:2452925700

selectsum(count_id) from (select count(object_id) count_id from leo4 group byobject_type)

call count cpu elapsed disk query current rows

------------- -------- ---------- -------------------- ---------- ----------

Parse 1 0.00 0.00 0 1 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.04 0.04 0 1030 0 1

------------- -------- ---------- -------------------- ---------- ----------

total 4 0.04 0.04 0 1031 0 1

Misses in librarycache during parse: 1

Optimizer mode:ALL_ROWS

Parsing user id:85

Rows Row Source Operation

------- ---------------------------------------------------

1 SORT AGGREGATE (cr=1030 pr=0 pw=0 time=0 us)

43 VIEW (cr=1030 pr=0 pw=0 time=588us cost=290 size=1006512 card=77424)

43 HASH GROUP BY (cr=1030 pr=0 pw=0 time=210 us cost=290 size=1858176card=77424)

71968 TABLE ACCESS FULL LEO4 (cr=1030 pr=0 pw=0 time=694104 us cost=287size=1858176 card=77424)

1.有1次硬解析

2.cpu time和elapsed time 0.04

3.行源操作需要处理4步才能完成，因此所用时间就会较长，效率较低

4.cr=1030 四个指标

5.由于是第二次统计，所以没有物理读，但所用的耗时却多

***************************************************************************************

五做一个较大的查询，分析sql_trace的原始文件，对整个trace文件的各部分内容进行语言性描述，特别留意数据处理过程中产生的等待事件及时长，思考整个过程中最消耗时间的操作是什么？

实验

LEO1@LEO1> droptable leo3 purge; 清理环境

Table dropped.

LEO1@LEO1>create table leo3 as select * from dba_objects; 创建leo3表

Table created.

LEO1@LEO1>insert into leo3 select * from leo3;

72007 rowscreated.

LEO1@LEO1>insert into leo3 select * from leo3;

144014 rowscreated.

LEO1@LEO1>insert into leo3 select * from leo3;

288028 rowscreated.

LEO1@LEO1>select count(*) from leo3; 我们插入了57w条数据

COUNT(*)

----------------

576056

LEO1@LEO1> altersession set sql_trace=true; 启动追踪SQL功能

Session altered.

LEO1@LEO1>select count(*) from (select * from leo3 order by object_id) a,(select * fromleo3 order by object_id) b where a.object_id=b.object_id; 执行一次大查询

COUNT(*)

-----------------

4608448

LEO1@LEO1> altersession set sql_trace=false; 关闭追踪SQL功能

Session altered.

退出SQLPLUS同样效果EXIT

LEO1@LEO1>select name,value from v$diag_info where name='Default Trace File';

NAME VALUE

----------------------------------------------------------------------------------------------------------------------------------------------

Default Trace File /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_25998.trc

当前会话默认写入的trace文件

我们来看看原始trace文件的内容

[oracle@leonarding1trace]$ vim LEO1_ora_25998.trc

=======================================================================================

PARSING IN CURSOR#4 len=549 dep=1 uid=85 ct=3 lid=85 tim=1360643355379273 hv=1384619666 ad='7f537b20'sqlid='cy3wbyd98g7nk'

SELECT/* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB)opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB)NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),NVL(SUM(C2),:"SYS_B_1"), COUNT(DISTINCT C3), NVL(SUM(CASE WHEN C3 ISNULL THEN :"SYS_B_2" ELSE :"SYS_B_3"END),:"SYS_B_4") FROM (SELECT /*+ NO_PARALLEL("LEO3")FULL("LEO3") NO_PARALLEL_INDEX("LEO3") */ :"SYS_B_5"AS C1, :"SYS_B_6" AS C2, "LEO3"."OBJECT_ID" AS C3FROM "LEO3" SAMPLE BLOCK (:"SYS_B_7" ,:"SYS_B_8") SEED (:"SYS_B_9") "LEO3") SAMPL,ESUB

END OFSTMT

PARSE#4:c=0,e=649,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1360643355379266

EXEC#4:c=1999,e=1465,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=893701161,tim=1360643355380831

FETCH#4:c=9998,e=11132,p=20,cr=85,cu=0,mis=0,r=1,dep=1,og=1,plh=893701161,tim=1360643355392015

STAT #4 id=1 cnt=1pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=85 pr=20 pw=0 time=0 us)'

STAT #4 id=2cnt=4702 pid=1 pos=1 bj=0 p='VIEW VW_DAG_0 (cr=85 pr=20 pw=0 time=125529 us cost=5 size=31356 card=603)'

STAT #4 id=3cnt=4702 pid=2 pos=1 bj=0 p='HASH GROUP BY (cr=85 pr=20 pw=0 time=25919 uscost=5 size=15075 card=603)'

STAT #4 id=4cnt=4764 pid=3 pos=1 bj=74154 p='TABLE ACCESS SAMPLE LEO3 (cr=85 pr=20 pw=0time=59412 us cost=4 size=15075 card=603)'

CLOSE#4:c=0,e=24,dep=1,type=0,tim=1360643355392298

PARSING IN CURSOR部分

说明：使用的是4号游标，这个游标号是可以重用的，这个游标指向的是我们执行的SQL产生的递归语句（红色部分），它是把对象属性写入数据字典中进行登记，好为以后的应用做语法语义校验的

len=549 执行的SQL长度

dep=1 递归的SQL深度，1层递归

uid=85 用户id 85代表leo1用户

oct=3 oracle commend type命令类型

lid=85 私有用户id 85也代表leo1用户

tim=1360643355379273 时间戳

hv=1384619666 have value SQL的哈希值

ad='7f537b20' SQL address SQL的地址

STAT部分

id=1 执行计划的行源号，每一层都有一个号，从上往下1 2 3 4排列

cnt=1 当前行源号返回的行数

pid=0 行源号的父号，如果当前行源号是4父号就是3 是1父号就是0

这也标识了执行计划的执行顺序4 -> 3 -> 2 -> 1

obj=74154 当前操作的对象id

LEO1@LEO1>select object_name from dba_objects where object_id=74154;这就是刚才我们操作的表名

OBJECT_NAME

--------------------

LEO3

op=TABLE ACCESSSAMPLE LEO3全表扫描行源的数据处理方式（也叫操作方式）

pos=1 执行计划中的位置

PARSE EXEC FETCH部分

c=0 消耗的CPU时间

e=649 这步操作的总用时

p=0 物理读的次数

cr=0 一致性读的次数（也叫数据块数），这个一致性读跟数据块在内存中还是硬盘中是没有关系的，它代表就需要读这么多次而已。如果要找的数据没有在内存中就会触发一次物理读

cu=0 current方式读的次数（数据块数）

mis=1 硬解析的次数

r=1 rows处理的行数

dep=1 递归的SQL深度

og=1 optimizer goal优化其模式

tim=1360643355379266 时间戳

plh=893701161 plan hash value 执行计划的哈希值

=======================================================================================

PARSING IN CURSOR#2 len=549 dep=1 uid=85 ct=3 lid=85 tim=1360643355392971 hv=1384619666 ad='7f537b20'sqlid='cy3wbyd98g7nk'

SELECT /*OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB)opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB)NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"),NVL(SUM(C2),:"SYS_B_1"), COUNT(DISTINCT C3), NVL(SUM(CASE WHEN C3 ISNULL THEN :"SYS_B_2" ELSE :"SYS_B_3"END),:"SYS_B_4") FROM (SELECT /*+ NO_PARALLEL("LEO3")FULL("LEO3") NO_PARALLEL_INDEX("LEO3") */ :"SYS_B_5"AS C1, :"SYS_B_6" AS C2, "LEO3"."OBJECT_ID" AS C3FROM "LEO3" SAMPLE BLOCK (:"SYS_B_7" ,:"SYS_B_8") SEED (:"SYS_B_9") "LEO3") SAMPLESUB

END OF STMT

PARSE#2:c=0,e=181,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=893701161,tim=1360643355392964

EXEC#2:c=0,e=227,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=893701161,tim=1360643355393267

FETCH#2:c=7999,e=8422,p=0,cr=85,cu=0,mis=0,r=1,dep=1,og=1,plh=893701161,tim=1360643355401734

STAT #2 id=1 cnt=1pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=85 pr=0 pw=0 time=0 us)'

STAT #2 id=2cnt=4702 pid=1 pos=1 bj=0 p='VIEW VW_DAG_0 (cr=85 pr=0 pw=0 time=224631 us cost=5 size=31356 card=603)'

STAT #2 id=3cnt=4702 pid=2 pos=1 bj=0 p='HASH GROUP BY (cr=85 pr=0 pw=0 time=41673 uscost=5 size=15075 card=603)'

STAT #2 id=4cnt=4764 pid=3 pos=1 bj=74154 p='TABLE ACCESS SAMPLE LEO3 (cr=85 pr=0 pw=0time=143391 us cost=4 size=15075 card=603)'

CLOSE#2:c=0,e=23,dep=1,type=0,tim=1360643355402144

=======================================================================================

PARSING IN CURSOR#9 len=134 dep=0 uid=85 ct=3 lid=85 tim=1360643355402676 hv=2179856754ad='81664b48' sqlid='b1t69vk0yvybk'

select count(*)from (select * from leo3 order by object_id) a,(select * from leo3 order byobject_id) b where a.object_id=b.object_id

END OF STMT

PARSE#9:c=24996,e=25529,p=20,cr=172,cu=0,mis=1,r=0,dep=0,og=1,plh=3063589819,tim=1360643355402670

EXEC#9:c=0,e=78,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3063589819,tim=1360643355403027

*** 2013-02-1212:29:18.222

FETCH#9:c=2805574,e=2819059,p=2103,cr=16402,cu=0,mis=0,r=1,dep=0,og=1,plh=3063589819,tim=1360643358222227

STAT #9 id=1 cnt=1pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=16402 pr=2103 pw=0 time=0 us)'

STAT #9 id=2cnt=4608448 pid=1 pos=1 bj=0 p='HASH JOIN (cr=16402 pr=2103 pw=0 time=63222024 us cost=6498 size=83495802card=3211377)'

STAT #9 id=3cnt=576056 pid=2 pos=1 bj=74154 p='TABLE ACCESS FULL LEO3 (cr=8201 pr=1689pw=0 time=3543486 us cost=2438 size=8822853 card=678681)'

STAT #9 id=4cnt=576056 pid=2 pos=2 bj=74154 p='TABLE ACCESS FULL LEO3 (cr=8201 pr=414pw=0 time=3369685 us cost=2438 size=8822853 card=678681)'

FETCH#9:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3063589819,tim=1360643358226922

*** 2013-02-1212:29:56.671

CLOSE#9:c=0,e=34,dep=0,type=0,tim=1360643396671376

=======================================================================================

[oracle@leonarding1trace]$ tkprof LEO1_ora_25998.trc sys=no 我们汇总一下看等待事件

output = 25998.txt

TKPROF: Release11.2.0.1.0 - Development on Tue Feb 12 14:43:31 2013

********************************************************************************

SQL ID:b1t69vk0yvybk

Plan Hash:3063589819

select count(*)

from

(select * from leo3 order by object_id)a,(select * from leo3 order by

object_id) b where a.object_id=b.object_id

call count cpu elapsed disk query current rows

------------- -------- ---------- -------------------- ---------- ----------

Parse 1 0.00 0.00 0 2 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 2.80 2.81 2103 16402 0 1

------------- -------- ---------- -------------------- ---------- ----------

total 4 2.81 2.82 2103 16404 0 1

Misses in librarycache during parse: 1

Optimizer mode:ALL_ROWS

Parsing user id:85

Rows Row Source Operation

------- ---------------------------------------------------

1 SORT AGGREGATE (cr=16402 pr=2103 pw=0 time=0 us)

4608448 HASH JOIN (cr=16402 pr=2103 pw=0 time=63222024 us cost=6498 size=83495802card=3211377)

576056 TABLE ACCESS FULL LEO3 (cr=8201 pr=1689 pw=0 time=3543486 us cost=2438size=8822853 card=678681)

576056 TABLE ACCESS FULL LEO3 (cr=8201 pr=414 pw=0 time=3369685 us cost=2438size=8822853 card=678681)

Elapsed timesinclude waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ---------------------------------------------

SQL*Net message to client 5 0.00 0.00

SQL*Net message from client 5 8.16 23.81

我们发现等待事件很少了哦，从这我们就可以看到等待事件及时长

time=63222024 显示最消耗时间的操作HASH JOIN

小结：后面这些都可以以此类推，掌握这些含义可以帮助我们了解sql执行中消耗了多少资源，实际的执行过程是什么样子的，产生了几层递归，数据如何被操作的。

（以上内容摘于网络，如有侵权，请告之，将第一时间删除）

相关文章

[上一篇] ORACLE 深入解析10053事件