1 为跟踪文件设置初始参数

1.检查设置 TIMED_STATISTICS, MAX_DUMP_FILE_SIZE, and USER_DUMP_DEST：

timed_statistics boolean TRUE

max_dump_file_size string UNLIMITED

user_dump_dest string /u01/app/oracle/admin/EMREP/udump

　查看以上三个参数：

Set linesize 1500;

col value for a50;

Col name for a30;

select name,type,value from v$parameter where name in ('timed_statistics','max_dump_file_size','user_dump_dest');　

2 为客户端ID启用跟踪

DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE程序为数据库指定的用户ID启用跟踪，　　　　　

DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(
   client_id    IN VARCHAR2,
   waits        IN BOOLEAN DEFAULT TRUE,
   binds        IN BOOLEAN DEFAULT FALSE);

Ａ. 为v$session中的client_identifier列附值:

默认v$session中的client_identifier列的值为空，可以通过创建trigger来给client_identifier列附加一个值:　　　　

CREATE OR REPLACE TRIGGER logon_trigger

AFTER LOGON ON DATABASE

DECLARE

uid VARCHAR2(64);

BEGIN

SELECT ora_login_user || '.' || SYS_CONTEXT('USERENV', 'OS_USER')

INTO uid

FROM dual;

dbms_session.set_identifier(uid);

END logon_trigger;

/

查看：

COL TRIGGERING_EVENT FOR A30;

select owner,trigger_name, TRIGGERING_EVENT，TABLE_NAME from dba_triggers where TRIGGER_NAME='LOGON_TRIGGER';

Ｂ.查看client_identifier列附值：

select username,SID, SERIAL#, CLIENT_identifier from v$session where username='TEST'；　　

EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(client_id => 'TEST.oracle',waits => TRUE, binds => FALSE);

EXECUTE DBMS_MONITOR.CLIENT_ID_TRACE_DISABLE(client_id => 'TEST.oracle');

３跟踪会话：

select sid,serial#,username from v$session where username is not null;

SID SERIAL# USERNAME

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

139 9726 TEST

140 43245 SYS

给指定的会话使用适当的值启用跟踪：

SQL>EXECUTE DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id =>139, serial_num => 9726,waits => TRUE, binds => FALSE);

TEST用户执行SQL：

SQL> create table test6 as select * from test2;

SQL> set linesize 1500;

SQL> col object_name for a40;

SQL> select * from test6;

SQL> update test6 set object_name='TEST' WHERE OBJECT_ID<20;

SQL> select * from test6;

SQL>EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id =>139, serial_num =>9726);

279 10 TEST

EXECUTE DBMS_MONITOR.SESSION_TRACE_DISABLE(session_id =>279, serial_num =>10);

使用10046 事件跟踪：

Level 0 tracing被关闭。这相当于设置sql_trace=false。

Level 1 跟踪sql语句，包括解析、执行、提取、提交和回滚等（SQL_TRACE=TRUE）。这是默认级别。

Level 4 SQL trace信息加绑定变量值(包括变量的详细信息)。

Level 8 SQL trace信息加等待事件信息。

Level 12 SQL trace 信息，等待事件信息，和绑定变量值。

跟踪当前的会话：

SQL> grant alter session to test;

SQL> conn test/test;

SQL> alter session set events '10046 trace name context forever ,level 12';

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

跟踪指定的会话：

SQL> select sid,serial#,username,status from v$session where username='TEST';

SID SERIAL# USERNAME

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

124 26742 TEST

方法一:

执行跟踪:

SQL> exec dbms_system.set_ev(148,2028,10046,8,''); ------------注意最后一个参数'',必须是这样的,而没有用户名

　　　 TEST用户执行SQL：

SQL> create table test6 as select * from test2;

SQL> set linesize 1500;

SQL> col object_name for a40;

SQL> select * from test6;

SQL> update test6 set object_name='TEST' WHERE OBJECT_ID<20;

SQL> select * from test6;

结束跟踪：

SQL> exec dbms_system.set_ev(148,2028,10046,0,'');

方法二（略过）:

SQL> select sid,serial#,username,status from v$session where username ='TEST';

SID SERIAL# USERNAME STATUS

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

124 26742 TEST KILLED

140 61014 TEST INACTIVE

148 2028 TEST KILLED

Session 1:

conn /as sysdba

exec dbms_system.set_ev(140,61014,10046,8,'test');

执行了这一步以后只是对其他的会话设置了跟踪事件的等级，并非开始跟踪

开始跟踪

exec dbms_system.set_sql_trace_in_session(140,61014,true);

....

在Session 2:

Conn test/test

中执行SQL 语句:

Select count(*) from user_tables;

Session 1:

结束跟踪

exec dbms_system.set_sql_trace_in_session(140,61014,false);

关闭会话设置

exec dbms_system.set_ev(140,61014,10046,0,'test');

使用10053事件跟踪：

如果想了解CBO的内部，还得通过10053事件，从10053事件的trace文件中，我们可以深入的了解CBO的内部，了解CBO是如何工作的，根据什么依据得出最终的执行计划。(10053事件的trace文件,我们只能直接阅读原始的trace文件,不能使用tkprof工具来处理)

10053事件有两个级别：

Level 2：2级是1级的一个子集

Level 1： 1级比2级更详细，它包含2级的所有内容.

设置本session的10053

开启：

Alter session set events’10053 trace name context forever[,level {1/2}]’;

关闭：

Alter session set events’10053 trace name context off’;

设置其他session的10053

开启：

SYS.DBMS_SYSTEM.SET_EV (, , 10053, {1|2}, '')

关闭：

SYS.DBMS_SYSTEM.SET_EV (, , 10053,0, '')

启动10053事件

SQL> grant alter session to test;

SQL> conn test/test;

SQL> ALTER SESSION SET EVENTS='10053 trace name context forever, level 1';

执行事务

SQL> select * from test2;

关闭10053事件

SQL> ALTER SESSION SET EVENTS '10053 trace name context off';

查找跟踪文件：

　　A:通过脚本查找(只能查找当前用户下的)：

select d.value||'/'||lower(rtrim(i.instance, chr(0)))||'_ora_'||p.spid||'.trc' trace_file_name from ( select p.spid from sys.v$mystat m,sys.v$session s,sys.v$process p where m.statistic# = 1 and s.sid = m.sid and p.addr = s.paddr) p, ( select t.instance from sys.v$thread t,sys.v$parameter v where v.name = 'thread' and (v.value = 0 or t.thread# = to_number(v.value))) i, ( select value from sys.v$parameter where name = 'user_dump_dest') d ;

　Ｂ:使用linux命令查找：

　　进入“ user_dump_dest”目录中：ll -t 命令，按时间显示最新产生的TRACE文件.跟踪文件格式为:“实例名_ora_进程号.trc”,user_dump_dest目录下查找对应进程的跟踪文件:

select spid from v$process where addr =(select paddr from v$session where sid='148' and serial#='2028');

４使用tkprof工具对trace文件进行分析。

一般来说，使用tkprof得到的输出文件中包含三个部分：

a.SQL语句本身。

b.相关的诊断信息，包括cpu时间、总共消耗的时间、读取磁盘数量、逻辑读的数量、以及查询中返回的记录数目。

c.列出这个语句的执行计划。

[oracle@secdb2 udump]$ tkprof

Usage: tkprof tracefile outputfile [explain= ] [table= ]

[print= ] [insert= ] [sys= ] [sort= ]

table=schema.tablename Use 'schema.tablename' with 'explain=' option.

explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.

print=integer List only the first 'integer' SQL statements.

aggregate=yes|no

insert=filename List SQL statements and data inside INSERT statements.

sys=no TKPROF does not list SQL statements run as user SYS.

record=filename Record non-recursive statements found in the trace file.

waits=yes|no Record summary for any wait events found in the trace file.

sort=option Set of zero or more of the following sort options:

prscnt number of times parse was called

prscpu cpu time parsing

prsela elapsed time parsing

prsdsk number of disk reads during parse

prsqry number of buffers for consistent read during parse

prscu number of buffers for current read during parse

prsmis number of misses in library cache during parse

execnt number of execute was called

execpu cpu time spent executing

exeela elapsed time executing

exedsk number of disk reads during execute

exeqry number of buffers for consistent read during execute

execu number of buffers for current read during execute

exerow number of rows processed during execute

exemis number of library cache misses during execute

fchcnt number of times fetch was called

fchcpu cpu time spent fetching

fchela elapsed time fetching

fchdsk number of disk reads during fetch

fchqry number of buffers for consistent read during fetch

fchcu number of buffers for current read during fetch

fchrow number of rows fetched

userid userid of user that parsed the cursor

其中比较有用的一个排序选项是fchela，即按照elapsed time fetching来对分析的结果排序（记住要设置初始化参数time_statistics=true），生成的.prf文件将把最消耗时间的sql放在最前面显示。另外一个有用的参数就是sys,这个参数设置为no可以阻止所有以sys用户执行的sql被显示出来，这样可以减少分析出来的文件的复杂度.

对Tkprof命令输出的解释：

CALL：每次SQL语句的处理都分成三个部分

Parse：这步将SQL语句转换成执行计划，包括检查是否有正确的授权和所需要用到的表、列以及其他引用到的对象是否存在。

Execute：这步是真正的由Oracle来执行语句。对于insert、update、delete操作，这步会修改数据，对于select操作，这步就只是确定选择的记录。

Fetch：返回查询语句中所获得的记录，这步只有select语句会被执行。

COUNT:这个语句被parse、execute、fetch的次数。

CPU：这个语句对于所有的parse、execute、fetch所消耗的cpu的时间，以秒为单位

ELAPSED：这个语句所有消耗在parse、execute、fetch的总的时间。

DISK：从磁盘上的数据文件中物理读取的块的数量。一般来说更想知道的是正在从缓存中读取的数据而不是从磁盘上读取的数据。

QUERY：在一致性读模式下，所有parse、execute、fetch所获得的buffer的数量。一致性模式的buffer是用于给一个长时间运行的事务提供一个一致性读的快照，缓存实际上在头部存储了状态。

CURRENT：在current模式下所获得的buffer的数量。一般在current模式下执行insert、update、delete操作都会获取buffer。在current模式下如果在高速缓存区发现有新的缓存足够给当前的事务使用，则这些buffer都会被读入了缓存区中。

ROWS: 所有SQL语句返回的记录数目，但是不包括子查询中返回的记录数目。对于select语句，返回记录是在fetch这步，对于insert、update、delete操作，返回记录则是在execute这步。

SQL语句的等待事件，对每种类型的等待事件提供了如下值。

Times Waited是等待事件占用时间。

Max. Wait是单个等待事件最大等待时间，单位为秒。

Total Waited是针对一个等待事件总的等待秒数。理想情况下，所有等待事件的等待时间总量应该等于执行统计提供的流逝时间与CPU时间的差值。该差值，如果存在，叫做未说明的时间（unaccounted for time）。

[oracle@secdb2 udump]$ tkprof emrep_ora_25724.trc ora_25724.prf sys=no SORT=FCHELA,PRSDSK,EXEDSK,FCHDSK PRINT = 10

TKPROF: Release 10.2.0.1.0 - Production on Sat Jan 26 07:29:37 2013

[oracle@secdb2 udump]$ cat ora_25724.prf |more

TKPROF: Release 10.2.0.1.0 - Production on Sat Jan 26 07:29:37 2013

Trace file: emrep_ora_25724.trc

Sort options: fchela prsdsk exedsk fchdsk

********************************************************************************

count = number of times OCI procedure was executed

cpu = cpu time in seconds executing

elapsed = elapsed time in seconds executing

disk = number of physical reads of buffers from disk

query = number of buffers gotten for consistent read

current = number of buffers gotten in current mode (usually for update)

rows = number of rows processed by the fetch or execute call

********************************************************************************

select *

from

t

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 3613 0.27 0.27 753 4324 0 54177

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

total 3615 0.28 0.28 753 4324 0 54177

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 62

Rows Row Source Operation

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

54177 TABLE ACCESS FULL T (cr=4324 pr=753 pw=0 time=162999 us)

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

SQL*Net message to client 3613 0.00 0.00

db file sequential read 1 0.00 0.00

db file scattered read 57 0.00 0.01

SQL*Net message from client 3613 1.30 160.52

********************************************************************************

…………...

********************************************************************************

Trace file: emrep_ora_25724.trc

Trace file compatibility: 10.01.00

Sort options: fchela prsdsk exedsk fchdsk

1 session in tracefile.

3 user SQL statements in trace file.

78 internal SQL statements in trace file.

81 SQL statements in trace file.

14 unique SQL statements in trace file.

11679 lines in trace file.

199 elapsed seconds in trace file.

说明：

cr为一致方式读取，显示一致读取数(逻辑I/O) pr 是物理读取 pw为物理写入 time=(以百万分之一秒计占用时间)。

ITPub博客

SQL跟踪工具和TKPROF使用

最新文章