一 数据库版本
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 oct=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 obj=0 op='SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)'
STAT #4 id=2cnt=72007 pid=1 pos=1 obj=74145 op='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 oct=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 obj=0 op='SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)'
STAT #2 id=2cnt=72007 pid=1 pos=1 obj=74145 op='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 oct=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 obj=0 op='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 obj=74145 op='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
Copyright (c)1982, 2009, Oracle and/or its affiliates. All rights reserved.
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
64
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 oct=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 obj=74150 op='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
64
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 oct=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 obj=74150 op='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(*)
----------
1
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 oct=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 obj=0 op='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 obj=74150 op='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(*)
----------
1
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 oct=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 obj=0 op='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 obj=74150 op='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
Copyright (c)1982, 2009, Oracle and/or its affiliates. All rights reserved.
********************************************************************************
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.由于是第二次统计，所以没有物理读，但所用的耗时却多
***************************************************************************************
本文转自 leonarding151CTO博客，原文链接：http://blog.51cto.com/leonarding/1133503，如需转载请自行联系原作者
