Oracle SQL_TRACE和10046事件优化SQL实例
一数据库版本LEO1@LEO1>select * from v$version;
BANNER
--------------------------------------------------------------------------------
Oracle Database11g Enterprise Edition>
PL/SQL> 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> 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则目录不同请注意
$ cd /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/
$ ll | grep LEO1_ora_8420.trc
显示没有这个文件，退出试试
LEO1@LEO1> exit
Disconnected fromOracle Database 11g Enterprise Edition> With thePartitioning, OLAP, Data Mining and Real Application Testing options
还是没有，后来我根据执行时间猜出是LEO1_ora_7455.trc这个文件，不知道是怎么回事
$ 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>
STAT #4> 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>
STAT #2> 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>
STAT #3> *** 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
$ tkprof LEO1_ora_7455.trc sql_trace.txt sys=no
TKPROF:> Copyright (c)1982, 2009, Oracle and/or its affiliates. All rights reserved.
sys=no参数表示过滤掉sys用户生成的递归语句，这样可以精简出比较好看的报告
$ vim sql_trace.txt
********************************************************************************
SQL> 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> Rows Row Source Operation
下面是SQL实际的执行计划，也有可能与autotrace不同，可以很方便的进行比对研究
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1031 pr=0 pw=0 time=0 us)
72007TABLE ACCESS FULL LEO1 (cr=1031 pr=0 pw=0 time=477183 us cost=288> ********************************************************************************
SQL> 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> Rows Row Source Operation 这个行源操作，就是SQL实际的执行过程
------- ---------------------------------------------------
43 HASH GROUP BY (cr=1031 pr=0 pw=0 time=0 us cost=290> 72007TABLE 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文件，是不是还是找不到呢，嗯你猜对了
$ ll | grep LEO1_ora_16565.trc 就像于谦唱的一无所有
LEO1@LEO1> exit leo1用户退出
Disconnected fromOracle Database 11g Enterprise Edition> With thePartitioning, OLAP, Data Mining and Real Application Testing options
LEO2@LEO1> exit leo2用户退出
Disconnected fromOracle Database 11g Enterprise Edition> With thePartitioning, OLAP, Data Mining and Real Application Testing options
$ 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> 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 STATUST 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> 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> *** 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> 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> 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=7f2e8344efa0bln=22 avl=02flg=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> *** 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> 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> 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> 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> 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>
STAT #4>
WAIT #4:nam='SQL*Net message to client'ela= 14 driver> *** 2013-02-0909:38:28.482
WAIT #4:nam='SQL*Net message from client' ela= 7797435 driver> 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> 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> 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=7f2e834ccec8bln=22 avl=02flg=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> 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> 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>
STAT #2>
WAIT #2:nam='SQL*Net message to client'ela= 18 driver> 又有等待事件的信息，也是我们常用的级别
*** 2013-02-0909:57:52.607
WAIT #2:nam='SQL*Net message from client' ela= 8167539 driver> 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>>
Session> 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> 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
$ tkprof LEO1_ora_25998.trc 25998_2.txt
TKPROF:> Copyright (c)1982, 2009, Oracle and/or its affiliates. All rights reserved.
********************************************************************************
SQL> 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> Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1030 pr=722 pw=0 time=0 us)
71968TABLE 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> 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> Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=1030 pr=0 pw=0 time=0 us)
43VIEW(cr=1030 pr=0 pw=0 time=588us cost=290>
43 HASH GROUP BY (cr=1030 pr=0 pw=0 time=210 us cost=290> 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>>
Session> 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>>
Session> 退出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文件的内容
$ 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>
STAT #4>
STAT #4>
STAT #4> 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 私有用户id85也代表leo1用户
tim=1360643355379273 时间戳
hv=1384619666 have valueSQL的哈希值
ad='7f537b20' SQL addressSQL的地址
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 执行计划中的位置
PARSEEXECFETCH部分
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>
STAT #2>
STAT #2>
STAT #2> 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>
STAT #9>
STAT #9>
STAT #9> 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
=======================================================================================
$ tkprof LEO1_ora_25998.trc sys=no 我们汇总一下看等待事件
output = 25998.txt
TKPROF:> Copyright (c)1982, 2009, Oracle and/or its affiliates. All rights reserved.
********************************************************************************
SQL> 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> 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> 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视频教程请关注:http://u.youku.com/user_video/id_UMzAzMjkxMjE2.html
页:
[1]