经典10046剖析案例-2

Posted Mr.Oracle

tags:

篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了经典10046剖析案例-2相关的知识，希望对你有一定的参考价值。

10046 trace的跟踪等级

10046是一个Oracle的内部事件(event)，通过设置这个事件可以得到Oracle内部执行系统解析、调用、等待、绑定变量等详细的trace信息，对于分析系统的性能有着非常重要的作用。

设置10046事件的不同级别能得到不同详细程度的trace信息，下面就列出各个不同级别的对应作用：

等级

二进制

作用

0

0000

无输出

1

0001

输出 ****,APPNAME（应用程序名）,PARSING IN CURSOR,PARSE ERROR（SQL解析）,EXEC（执行）,FETCH（获取数据）,UNMAP,SORT UNMAP（排序，临时段）,ERROR,STAT（执行计划）,XCTEND（事务）等行

2

0011

与等级1完全一样

4

0101

包括等级1的输出，加上BIND行（绑定变量信息）

8

1001

包括等级1的输出，加上WAIT行（等待事件信息）

12

1101

输出等级1、等级4以及等级8的所有信息

等级1的10046 trace被视为是普通的SQL Trace，而等级4、等级8以及等级12则被称为Extended SQL Trace，Extended SQL Trace里面包括了最有用的WAIT信息，因此在实际中也是用的最多的。

与SQL Trace相关的参数

在打开10046时间的SQL Trace之前，要先设置好下面几个参数。

timed_statistics

这个参数决定了是否收集与时间相关的统计信息，如果这个参数为FALSE的话，那么SQL Trace的结果基本没有多大的用处，默认情况下这个参数设置为TRUE。

max_dump_file_size

dump文件的大小，也就是决定是否限制SQL Trace文件的大小，在一个很忙的系统上面做SQL Trace的话可能会生成很多的信息，因此最好在会话级别将这个参数设置成unlimited。

tracefile_identifier

给Trace文件设置识别字符串，这是个非常有用的参数，设置一个易读的字串能更快的找到Trace文件。

要在当前会话修改上述参数很简单，只要使用下面的命令即可：

1

2

3

ALTER SESSION SET timed_statistics=true

ALTER SESSION SET max_dump_file_size=unlimited

ALTER SESSION SET tracefile_identifier=‘my_trace_session

当然，这些参数可以在系统级别修改的，也可以加载init文件中或是spfile中，让系统启动时自动做全局设置。

要是在系统运行时动态的修改别的会话的这些参数就需要借助DBMS_SYSTEM这个包了，设置方法如下：

1

2

3

4

5

6

7

8

9

SYS.DBMS_SYSTEM.SET_BOOL_PARAM_IN_SESSION(

  :sid, :serial,

  ‘timed_statistics‘, true

)

 

SYS.DBMS_SYSTEM.SET_INT_PARAM_IN_SESSION(

  :sid, :serial,

  ‘max_dump_file_size‘, 2147483647

)

注意，Oracle并没有提供一个set_string_param_in_session的函数在dbms_system包中，因此tracefile_identifier是无法在别的会话中修改的（至少我到现在没有找到一个可以设置的方法）。

10046 Trace启动方法

开启当前会话的10046 Trace

使用sql_trace参数

sql_trace应该是简单快捷的开启Trace的方法了，不过通过sql_trace只能开启级别为1的Trace，而无法开启其他更高级的Trace。

1

2

3

4

5

-- 开启Trace

ALTER SESSION SET sql_trace=true;

 

-- 关闭Trace

ALTER SESSION SET sql_trace=false;

使用set event开启Trace

使用set event打开10046事件Trace是最常用的了。

1

2

3

4

5

-- 开启级别为12的Trace，level后面的数字设置了Trace的级别

ALTER SESSION SET EVENTS ‘10046 trace name context forever, level 12‘

 

-- 关闭Trace，任何级别

ALTER SESSION SET EVENTS ‘10046 trace name context off‘

开启其他会话的10046 Trace

使用登陆触发器开启Trace

我们可以通过编写登陆触发器来开启10046 Trace，使用这种方法开启Trace的代码和开启当前会话的是一样的，不同的就是这些开启代码是包含在一个after logon触发器里面的。

1

2

3

4

5

6

7

8

9

10

-- 代码来自《Optimazing Oracle Performance》 P116

CREATE OR REPLACE TRIGGER trace_test_user AFTER LOGON ON DATABASE

BEGIN

  IF USER LIKE ‘%\_test‘ ESCAPE ‘\‘ THEN

    EXECUTE IMMEDIATE ‘ALTER SESSION SET timed_statistics=true‘;

    EXECUTE IMMEDIATE ‘ALTER SESSION SET max_dump_file_size=unlimited‘;

    EXECUTE IMMEDIATE ‘ALTER SESSION SET EVENTS ‘‘10046 trace name context forever, level 8‘‘ ‘;

  END IF;

END;

/

使用oradebug工具

使用oradebug工具必须要知道所要处理的进程的OS进程PID，OS PID可以使用下面的语句得到：

1

2

3

4

5

6

SELECT S.USERNAME,

    P.SPID OS_PROCESS_ID,

    P.PID ORACLE_PROCESS_ID

FROM V$SESSION S, V$PROCESS P

WHERE S.PADDR = P.ADDR

    AND S.USERNAME = UPPER(‘&USER_NAME‘);

得到PID之后就可以使用oradebug工具了，注意需要使用sysdba登陆到数据库：

1

2

3

4

5

6

7

8

-- 假设9999为会话的OS PID

oradebug setospid 9999;

-- 设置Trace文件大小

oradebug unlimit;

-- 开启级别为12的Trace

oradebug event 10046 trace name context forever ,level 12;

--关闭trace

Oradebug event 10046 trace name context off;

使用DBMS_SYSTEM包

DBMS_SYSTEM包提供了两个开启10046 Trace的方法，一个是使用SET_SQL_TRACE_IN_SESSION过程，不过使用这个过程的效果和sql_trace是一样的：

1

2

3

4

5

-- 开启Trace

EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(:sid, :serial#, true);

 

-- 关闭Trace

EXEC SYS.DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(:sid, :serial#, false);

另一个方法是使用SET_EV过程，当然这个过程不仅仅用来设置10046事件，还能设置所有的其他的事件，使用方法为：

1

2

3

4

5

6

7

8

PROCEDURE SET_EV

 Argument Name                  Type                    In/Out Default?

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

 SI                             BINARY_INTEGER          IN

 SE                             BINARY_INTEGER          IN

 EV                             BINARY_INTEGER          IN

 LE                             BINARY_INTEGER          IN

 NM                             VARCHAR2                IN

使用例子：

1

2

3

4

5

-- 开启level 12的Trace

EXEC SYS.DBMS_SYSTEM.SET_EV(:sid, :serial, 10046, 12, ‘‘);

 

-- 关闭Trace

EXEC SYS.DBMS_SYSTEM.SET_EV(:sid, :serial, 10046, 0, ‘‘);

使用DBMS_SUPPORT包

DBMS_SUPPORT包默认情况下并没有包含在数据库中，需要通过运行$ORACLE_HOME/rdbms/admin/dbmssupp.sql安装之后才能使用。

可以DBMS_SUPPORT包来开启自身进程或者是别的进程的Trace。

开启自身进程：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

-- 使用方法

DESC DBMS_SUPPORT

 

PROCEDURE START_TRACE

 Argument Name                  Type                    In/Out Default?

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

 WAITS                          BOOLEAN                 IN     DEFAULT

 BINDS                          BOOLEAN                 IN     DEFAULT

PROCEDURE STOP_TRACE

 

-- 实例

-- 开启级别为12的Trace

EXEC SYS.DBMS_SUPPORT.START_TRACE(true, true);

 

-- 关闭Trace

EXEC SYS.DBMS_SUPPORT.STOP_TRACE();

开启其他进程的Trace：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

-- 使用方法

PROCEDURE START_TRACE_IN_SESSION

 Argument Name                  Type                    In/Out Default?

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

 SID                            NUMBER                  IN

 SERIAL                         NUMBER                  IN

 WAITS                          BOOLEAN                 IN     DEFAULT

 BINDS                          BOOLEAN                 IN     DEFAULT

PROCEDURE STOP_TRACE_IN_SESSION

 Argument Name                  Type                    In/Out Default?

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

 SID                            NUMBER                  IN

 SERIAL                         NUMBER                  IN

 

-- 实例

-- 开启级别为12的Trace

EXEC SYS.DBMS_SUPPORT.START_TRACE_IN_SESSION(:sid, :serial, true, true);

 

-- 关闭Trace

EXEC SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION(:sid, :serial);

使用DBMS_MONITOR包

Oracle 10g中DBMS_MONITOR包的出现改变了以往一次只能开启一个会话的历史，开启了一个批量启用10046 Trace的新纪元。

追踪单个会话

首先看看与前面类似的开启单个会话的Trace的方法，这个时候与DBMS_SUPPORT包是几乎没有区别的：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

-- 过程定义

PROCEDURE SESSION_TRACE_DISABLE

 Argument Name                  Type                    In/Out Default?

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

 SESSION_ID                     BINARY_INTEGER          IN     DEFAULT

 SERIAL_NUM                     BINARY_INTEGER          IN     DEFAULT

PROCEDURE SESSION_TRACE_ENABLE

 Argument Name                  Type                    In/Out Default?

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

 SESSION_ID                     BINARY_INTEGER          IN     DEFAULT

 SERIAL_NUM                     BINARY_INTEGER          IN     DEFAULT

 WAITS                          BOOLEAN                 IN     DEFAULT

 BINDS                          BOOLEAN                 IN     DEFAULT

 PLAN_STAT                      VARCHAR2                IN     DEFAULT

 

-- 实例

-- 开启级别为12的Trace，当前会话

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(WAITS=>true,BINDS=>true);

-- 开启级别为12的Trace，其他会话

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(:sid, :serial, true, true);

 

-- 关闭Trace，当前会话

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE();

-- 关闭Trace，其他会话

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(:sid, :serial);

根据Client Identifier追踪

使用DBMS_MONITOR包也许同根据client identifier来Trace多个不同的会话，client identifier可以通过V$SESSION里面client_identifier字段看到，使用方法如下：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

-- 找出要Trace的client_identifier信息

SQL> SELECT sid, program, client_identifier FROM V$SESSION;

 

       SID PROGRAM                                          CLIENT_IDENTIFIER

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

        71 [email protected] (TNS V1-V3)     [email protected]

        72 [email protected] (TNS V1-V3)        [email protected]

        75 [email protected] (TNS V1-V3)        [email protected]

 

-- 假设要Trace client_identifier是“[email protected]”的所有会话

-- 使用下面的语句即可，开启一个level 12的Trace

SQL> EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(‘[email protected]‘, true, true);

PL/SQL procedure successfully completed.

 

-- 使用下面语句停止

EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE(‘[email protected]‘);

根据Service, Module和Action追踪

DBMS_MONITOR包的SERV_MOD_ACT_TRACE_ENABLE过程用来根据Service, Module和Action三个属性开启多个会话的Trace。

在进行Trace之前要确保你的应用程序设置了这三个相应的属性，Oracle提供了包DBMS_APPLICATION_INFO用来设置module、action等信息，使用方法如下：

1

2

3

EXEC dbms_application_info.SET_MODULE(‘Trace Test‘, ‘No Trace‘);

EXEC DBMS_APPLICATION_INFO.SET_ACTION(‘‘No Trace‘);

EXEC DBMS_APPLICATION_INFO.SET_CLIENT_INFO(‘A Haaaa‘);

设置完成之后我们就可以在V$SESSION看到这些信息了：

1

2

3

4

5

6

7

8

9

10

11

SQL> COL ACTION FOR A10

SQL> COL MODULE FOR A45

SQL> COL SERVICE_NAME FOR A12

SQL> COL SID FOR 999

SQL> SELECT SID , service_name, module, action FROM v$session WHERE TYPE<>‘BACKGROUND‘;

 

 SID SERVICE_NAME MODULE                                        ACTION

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

  67 SYS$USERS    SQL Developer

  71 SYS$USERS    [email protected] (TNS V1-V3)

  72 SYS$USERS    Trace Test                                    No Trace

知道了相应的信息再使用DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE来启用对相应会话的Trace：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

-- 针对service name为“SYS$USERS”的所有会话开启Trace

EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(service_name => ‘SYS$USERS‘,

        waits => TRUE, binds => FALSE);

 

-- 停止所开启的Trace

EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(service_name => ‘SYS$USERS‘);

 

-- 针对特定的action开启Trace

EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(service_name=>‘SYS$USERS‘,

    module_name=>‘Trace Test‘,

    action_name => ‘Trace‘,

    waits => TRUE, binds => FALSE);

 

-- 停止所开启的Trace

EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(service_name=>‘SYS$USERS‘,

    module_name=>‘Trace Test‘,

    action_name => ‘Trace‘)

开启数据库级的Trace

DBMS_MONITOR还能开启数据库级别的Trace。

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

-- 定义

PROCEDURE DATABASE_TRACE_DISABLE

 Argument Name                  Type                    In/Out Default?

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

 INSTANCE_NAME                  VARCHAR2                IN     DEFAULT

PROCEDURE DATABASE_TRACE_ENABLE

 Argument Name                  Type                    In/Out Default?

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

 WAITS                          BOOLEAN                 IN     DEFAULT

 BINDS                          BOOLEAN                 IN     DEFAULT

 INSTANCE_NAME                  VARCHAR2                IN     DEFAULT

 PLAN_STAT                      VARCHAR2                IN     DEFAULT

 

-- 开启数据库级的level 12的Trace

EXEC DBMS_MONITOR.DATABASE_TRACE_ENABLE(true, true);

 

-- 停止数据库级的Trace

EXEC DBMS_MONITOR.DATABASE_TRACE_DISABLE();

这个功能影响整个数据库，很强大，慎用！

开启多个会话Trace的注意点

使用DBMS_MONITOR开启多个会话的Trace是动态的，比如说当你要追踪某个特定的action的Trace的时候，你并不需要先确定那个特定的action对应的会话正在运行中才能开启相应的Trace，相反的是一旦某个进程的action满足当前开启的Trace的条件的时候，那个会话就会开始输出Trace信息，当会话的action发生改变之后，Trace信息也会停止输出，下面是一个简单的测试。

先在一个进程中开始针对module为“Trace Test”，action为“Trace”的Trace：

1

2

3

4

5

6

SQL> EXECUTE DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(service_name=>‘SYS$USERS‘,

module_name=>‘Trace Test‘,

action_name => ‘Trace‘,

waits => TRUE, binds => FALSE);

 

PL/SQL procedure successfully completed.

然后在另外一个进程中执行下面的一序列语句：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

-- 设置当前会话的module和action

SQL> EXEC DBMS_APPLICATION_INFO.SET_MODULE(‘Trace Test‘, ‘Trace‘);

 

PL/SQL procedure successfully completed.

 

-- 执行一个简单的查询

SQL> select ‘trace‘ from dual;

 

TRACE

------

trace

 

-- 改变当前会话的action

SQL> EXEC DBMS_APPLICATION_INFO.SET_MODULE(‘Trace Test‘, ‘No Trace‘);

 

PL/SQL procedure successfully completed.

 

-- 再执行另一个查询

SQL> select ‘no trace‘ from dual;

 

NOTRACE

--------

no trace

执行完毕之后打开Trace文件就会发现第一次执行module、action设置的语句和第二次执行的“select ‘no trace’ from dual;”都没有出现在Trace文件，Trace文件内容如下：

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

37

38

39

40

41

42

43

44

45

Unix process pid: 8900, image: [email protected] (TNS V1-V3)

 

 

*** 2010-04-13 06:55:24.247

*** SESSION ID:(72.604) 2010-04-13 06:55:24.247

*** CLIENT ID:([email protected]) 2010-04-13 06:55:24.247

*** SERVICE NAME:(SYS$USERS) 2010-04-13 06:55:24.247

*** MODULE NAME:(Trace Test) 2010-04-13 06:55:24.247

*** ACTION NAME:(Trace) 2010-04-13 06:55:24.247

 

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

PARSING IN CURSOR #1 len=69 dep=0 uid=0 oct=47 lid=0 tim=1271141724247208 hv=297401484 ad=‘9eb182c8‘ sqlid=‘1ckkjdn8vmz4c‘

BEGIN DBMS_APPLICATION_INFO.SET_MODULE(‘Trace Test‘, ‘Trace‘); END;

END OF STMT

EXEC #1:c=0,e=113,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1271141724247201

WAIT #1: nam=‘SQL*Net message to client‘ ela= 6 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271141724247735

 

*** 2010-04-13 06:55:32.913

WAIT #1: nam=‘SQL*Net message from client‘ ela= 8666025 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271141732913790

CLOSE #1:c=0,e=43,dep=0,type=0,tim=1271141732913937

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

PARSING IN CURSOR #2 len=25 dep=0 uid=0 oct=3 lid=0 tim=1271141732932795 hv=660028772 ad=‘9eb12b10‘ sqlid=‘70t5xg4mpfgb4‘

select ‘trace ‘ from dual

END OF STMT

PARSE #2:c=1000,e=18805,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1271141732932792

EXEC #2:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1271141732932946

WAIT #2: nam=‘SQL*Net message to client‘ ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271141732932989

FETCH #2:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1271141732933035

STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op=‘FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)‘

WAIT #2: nam=‘SQL*Net message from client‘ ela= 151 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271141732933287

FETCH #2:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1271141732933331

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

 

*** 2010-04-13 06:55:48.413

WAIT #2: nam=‘SQL*Net message from client‘ ela= 15480453 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1271141748413833

CLOSE #2:c=0,e=26,dep=0,type=0,tim=1271141748413963

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

PARSING IN CURSOR #1 len=72 dep=0 uid=0 oct=47 lid=0 tim=1271141748415935 hv=2176830839 ad=‘9eb0ec80‘ sqlid=‘ar765n60vzmbr‘

BEGIN DBMS_APPLICATION_INFO.SET_MODULE(‘Trace Test‘, ‘No Trace‘); END;

END OF STMT

PARSE #1:c=1999,e=1919,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1271141748415932

*** MODULE NAME:(Trace Test) 2010-04-13 06:55:48.416

*** ACTION NAME:(No Trace) 2010-04-13 06:55:48.416

 

EXEC #1:c=0,e=93,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1271141748416134

以上是关于经典10046剖析案例-2的主要内容，如果未能解决你的问题，请参考以下文章

经典10046剖析案例-3

经典10046剖析案例-1

经典10046剖析案例-4

知识图谱实战开发案例剖析

知识图谱实战开发案例剖析

高并发和海量数据下的 9 个 Redis 经典案例剖析！