oracle 10046使用学习

设置10046事件来进行SQL跟踪，可以设置不同的跟踪级别

Level 0   停用SQL跟踪，相当于SQL_TRACE=FALSE

Level 1   标准SQL跟踪，相当于SQL_TRACE=TRUE

Level 4   在level 1的基础上增加绑定变量的信息

Level 8   在level 1的基础上增加等待事件的信息

Level 12 在level 1的基础上增加绑定变量和等待事件的信息

 

启用跟踪事件10046

 

10046事件由于跟踪的事件不同，生成的文档的目录也不相同，跟踪用户会话(trace文件位于USER_DUMP_DEST )，跟踪background进程(trace文件位于BACKGROUND_DUMP_DEST )。

 

1.在全局设置

修改初始化参数

EVENT = "10046 trace name context forever, level 8"

2.在当前session设置

alter session set events '10046 trace name context forever, level 8';

alter session set events '10046 trace name context off';

 

测试实例

SQL> set serverout on;
SQL> alter session set events '10046 trace name context forever, level 8';

Session altered

 

--为了查看生产文件省事，设置一个添加名称

SQL> alter session set tracefile_identifier='yuzh';

Session altered

 

SQL>执行语句

执行结果

 

--查看结果所在目录

SQL> show parameter user_dump_dest;

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest                       string      /u01/app/oracle/admin/CNDBS1T9/udump

 

--如果不设置别名，通过如下语句得到目标文件
SQL> select d.value || '/' || lower(rtrim(i.instance, chr(0))) || '_ora_' ||p.spid|| '.trc' trace_file_name
  2           from (select p.spid
  3                from v$mystat m, v$session s, v$process p
  4               where m.statistic# = 1
  5                 and s.sid = m.sid
  6                 and p.addr = s.paddr) p,
  7             (select t.instance
  8                from v$thread t, v$parameter v
  9              where v.name = 'thread'
 10                and (v.value = 0 or t.thread# = to_number(v.value))) i,
 11            (select value from v$parameter where name = 'user_dump_dest') d;

TRACE_FILE_NAME
--------------------------------------------------------------------------------
/u01/app/oracle/admin/CNDBS1T9/udump/cndbs1t9_ora_17764.trc

 

--如果设置了别名，其实上述语句得出的文件也还是可用的，不过还是使用别名文件最好，文件名称如下

cndbs1t9_ora_17764_yuzh.trc

 

 --直接解读可能比较困难，我们使用tkprof来解析一下

oracle@shdb06t $ tkprof cndbs1t9_ora_17764_yuzh.trc 123.txt

TKPROF: Release 10.2.0.4.0 - Production on Tue Aug 24 15:07:17 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

oracle@shdb06t $ cat 123.txt

 

解析结果如下：

 

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

select * 
from
 GMS_IVC.IVC_STOCK_COST b where b.enterprise_group_code=:"SYS_B_0" and 
  b.company_code=:"SYS_B_1" and b.unit_price=:"SYS_B_2" and b.stock_date=
  to_date(:"SYS_B_3",:"SYS_B_4")

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        1      0.14       3.79       1023      21561          0          74
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.14       3.79       1023      21561          0          74

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
     74  TABLE ACCESS BY INDEX ROWID IVC_STOCK_COST (cr=21561 pr=1023 pw=0 time=2741575 us)
  24351   INDEX SKIP SCAN IVC_STOCK_COST_PK (cr=139 pr=139 pw=0 time=2405079 us)(object id 106381)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.22          0.23
  db file sequential read                      1023        0.02          3.67
  SQL*Net more data to client                     1        0.00          0.00
********************************************************************************

begin
  sys.dbms_output.get_line(line => :line, status => :status);
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.01          0        171          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.01          0        171          0           2

Misses in library cache during parse: 2
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.03          0.05
********************************************************************************

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

--一般需调优的评估量就是disk      query    current        这三个指标

 

--关闭10046

alter session set events '10046 trace name context off';

 

 

3.对其他用户session设置

 

首先获得要跟踪的session的sid和serial number

具体获得方式看具体状况

select sid,serial#,username from v$session where username='TRACE_USERNAME';

select sid,serial#,username from v$session where sql_id='*****';

 

测试实例：

sid＝517 ，serial#＝5178

 

dbms_support方式：

--创建监控使用的包

SQL> @/u01/app/oracle/product/10.2.0/db_1/rdbms/admin/dbmssupp.sql;

Package created.

Package body created.

 

SQL> exec dbms_support.start_trace_in_session(sid => 517,serial => 5178,waits => true,binds => true);

PL/SQL procedure successfully completed

 

SQL> exec dbms_support.stop_trace_in_session(sid => 517,serial => 5178);

PL/SQL procedure successfully completed

 

--查看目标文件名称

SQL> select d.value || '/' || lower(rtrim(i.instance, chr(0))) || '_ora_' ||p.spid|| '.trc' trace_file_name
  2           from (select p.spid
  3                from  v$session s, v$process p
  4               where s.sid=517
  5                 and p.addr = s.paddr) p,
  6             (select t.instance
  7                from v$thread t, v$parameter v
  8              where v.name = 'thread'
  9                and (v.value = 0 or t.thread# = to_number(v.value))) i,
 10            (select value from v$parameter where name = 'user_dump_dest') d;

TRACE_FILE_NAME
--------------------------------------------------------------------------------
/u01/app/oracle/admin/CNDBS1T9/udump/cndbs1t9_ora_19347.trc

 

--解析目标文件

oracle@shdb06t $ tkprof cndbs1t9_ora_19347.trc 234.txt

TKPROF: Release 10.2.0.4.0 - Production on Tue Aug 24 15:54:54 2010

Copyright (c) 1982, 2007, Oracle.  All rights reserved.

 

oracle@shdb06t $ cat 234.txt

 

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

select * 
from
 GMS_IVC.IVC_STOCK_COST b where b.enterprise_group_code=:"SYS_B_0" and 
  b.company_code=:"SYS_B_1" and b.unit_price=:"SYS_B_2" and b.stock_date=
  to_date(:"SYS_B_3",:"SYS_B_4")

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.08       0.07          0      21561          0          74
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.09       0.08          0      21561          0          74

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
     74  TABLE ACCESS BY INDEX ROWID IVC_STOCK_COST (cr=21561 pr=0 pw=0 time=13993 us)
  24351   INDEX SKIP SCAN IVC_STOCK_COST_PK (cr=139 pr=0 pw=0 time=24564 us)(object id 106381)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.00
  SQL*Net more data to client                     1        0.00          0.00
********************************************************************************

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

 

 

dbms_system方式

 

SQL> exec dbms_system.set_ev( 517, 5178, 10046, 8, '');

PL/SQL procedure successfully completed

SQL> exec dbms_system.set_ev( 517, 5178, 10046, 0, '');

PL/SQL procedure successfully completed

 

--结果解析方法如上，结果如下

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

select * 
from
 GMS_IVC.IVC_STOCK_COST b where b.enterprise_group_code=:"SYS_B_0" and 
  b.company_code=:"SYS_B_1" and b.unit_price=:"SYS_B_2" and b.stock_date=
  to_date(:"SYS_B_3",:"SYS_B_4")

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.01       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.20       3.63       1047      43254          0         148
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.21       3.64       1047      43254          0         148

Misses in library cache during parse: 2
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
     74  TABLE ACCESS BY INDEX ROWID IVC_STOCK_COST (cr=21561 pr=0 pw=0 time=13993 us)
  24351   INDEX SKIP SCAN IVC_STOCK_COST_PK (cr=139 pr=0 pw=0 time=24564 us)(object id 106381)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       4        0.00          0.00
  SQL*Net message from client                     4        0.01          0.02
  SQL*Net more data to client                     2        0.00          0.00
  db file sequential read                      1047        0.01          3.45
********************************************************************************

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

 

 

dbms_monitor方式：

 

SQL> exec dbms_monitor.session_trace_enable(session_id => 517,serial_num => 5178,waits => true,binds => true);

PL/SQL procedure successfully completed

SQL> exec dbms_monitor.session_trace_disable(session_id => 517,serial_num => 5178);

PL/SQL procedure successfully completed

 

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

select * 
from
 GMS_IVC.IVC_STOCK_COST b where b.enterprise_group_code=:"SYS_B_0" and 
  b.company_code=:"SYS_B_1" and b.unit_price=:"SYS_B_2" and b.stock_date=
  to_date(:"SYS_B_3",:"SYS_B_4")

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.01       0.01          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        3      0.36       7.64       2190      65586          0         222
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        9      0.37       7.66       2190      65586          0         222

Misses in library cache during parse: 3
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
-------  ---------------------------------------------------
     74  TABLE ACCESS BY INDEX ROWID IVC_STOCK_COST (cr=21561 pr=0 pw=0 time=13993 us)
  24351   INDEX SKIP SCAN IVC_STOCK_COST_PK (cr=139 pr=0 pw=0 time=24564 us)(object id 106381)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       6        0.00          0.00
  SQL*Net message from client                     6        0.01          0.02
  SQL*Net more data to client                     3        0.00          0.00
  db file sequential read                      2190        0.02          7.32
********************************************************************************

timed_statistics的理解
关于参数timed_statistics的一段解说
Without timed statistics, Oracle records the reason for each wait before it begins to wait, and when the wait is over, it records whether it timed out. But with timed statistics enabled, Oracle checks the time just before and after each wait, and also records the time waited. The time waited is recorded in hundredths of a second— that is, centiseconds.


本人的理解是:参数timed_statistics没有设置的话.Oracle只记录wait开始和wait结束这一段时间内的wait reason和wait结束是否是因为timed out.而设置timed_statistics=true后.Oracle就记录了wait的时间信息.有了这些时间信息可以确定等待事件在哪个时间段出现比较频繁.   请指正


在timed_statistics  = false时,我们只能够知道这些等待时间的次数(records the reason for each wait ), 以及等待时间timed out的次数(records whether it timed out)


在timed_statistics = true时,我们可以知道系统在某个具体的等待事件上等待的时间(records the time waited),这样我们就可以判断具体是什么原因导致我们的系统变慢或者.