拜年+散分贴《Oracle SQL_TRACE和10046事件优化SQL实例》

本文涉及的产品
云解析 DNS,旗舰版 1个月
全局流量管理 GTM,标准版 1个月
公共DNS(含HTTPDNS解析),每月1000万次HTTP解析
简介:

 数据库版本

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_TRACE10046事件对其它会话进行跟踪,并给出trace结果

SQL_TRACEOracle这个功能主要是为了追踪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 TRACE1.输出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 NUMBERSessionidentifier   就是会话标识

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=12SERIAL=4472SQL

声明:这个存储过程是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=12SERIAL=4472SQLexit 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个会话的IDSERIAL

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:事件号

12level级别

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_TRACE10046事件内容是按时间顺序打印出来的,过程如上所示

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,如需转载请自行联系原作者





相关文章
|
22天前
|
SQL 缓存 监控
大厂面试高频:4 大性能优化策略(数据库、SQL、JVM等)
本文详细解析了数据库、缓存、异步处理和Web性能优化四大策略,系统性能优化必知必备,大厂面试高频。关注【mikechen的互联网架构】,10年+BAT架构经验倾囊相授。
大厂面试高频:4 大性能优化策略(数据库、SQL、JVM等)
|
1月前
|
SQL 存储 缓存
如何优化SQL查询性能?
【10月更文挑战第28天】如何优化SQL查询性能?
93 10
|
1月前
|
SQL 存储 缓存
SQL Server 数据太多如何优化
11种优化方案供你参考,优化 SQL Server 数据库性能得从多个方面着手,包括硬件配置、数据库结构、查询优化、索引管理、分区分表、并行处理等。通过合理的索引、查询优化、数据分区等技术,可以在数据量增大时保持较好的性能。同时,定期进行数据库维护和清理,保证数据库高效运行。
|
1月前
|
SQL Oracle 关系型数据库
Oracle数据库优化方法
【10月更文挑战第25天】Oracle数据库优化方法
40 7
|
1月前
|
存储 Oracle 关系型数据库
Oracle数据库优化策略
【10月更文挑战第25天】Oracle数据库优化策略
25 5
|
2月前
|
SQL 资源调度 分布式计算
如何让SQL跑快一点?(优化指南)
这篇文章主要探讨了如何在阿里云MaxCompute(原ODPS)平台上对SQL任务进行优化,特别是针对大数据处理和分析场景下的性能优化。
|
2月前
|
SQL 数据管理 数据库
SQL语句实例教程:掌握数据查询、更新与管理的关键技巧
SQL(Structured Query Language,结构化查询语言)是数据库管理和操作的核心工具
|
2月前
|
SQL 监控 数据库
慢SQL对数据库写入性能的影响及优化技巧
在数据库管理系统中,慢SQL(即执行缓慢的SQL语句)不仅会影响查询性能,还可能对数据库的写入性能产生显著的不利影响
|
2月前
|
SQL 监控 Oracle
Oracle SQL性能优化全面指南
在数据库管理领域,Oracle SQL性能优化是确保数据库高效运行和数据查询速度的关键
|
2月前
|
SQL 存储 Oracle
Oracle数据库SQL语句详解与应用指南
在数字化时代,数据库已成为各类企业和组织不可或缺的核心组件。Oracle数据库作为业界领先的数据库管理系统之一,广泛应用于各种业务场景。掌握Oracle数据库的SQL语句是数据库管理员、开发人员及运维人员的基本技能。本文将详细介绍Oracle数据库SQL语句的基本概念、语法、应用及最佳实践。一、Or
64 3

推荐镜像

更多