Oracle 10g sql trace使用

sql trace 平时主要用在针对性的性能监控上，针对某个用户的会话，或者自己的会话。

系统级别跟踪，生产库慎用，会付出较高的性能代价。具体没有亲身测试过。

这里主要简单介绍下常规的trace使用。

一：对自己的SESSION进行跟踪

1：首先开启针对这个会话的sql trace.

alter session set sql_trace true ;

2:执行要追踪的sql语句

select count(*) from  TBL_FL_FT_NEWUSERS ;

稍等片刻之后，我一般是等待语句执行结束，语句没有执行结束，会不会影响trace结果，这个需要亲自验证。

3：结束trace.

alter session set sql_trace false ;

系统会生成trace文件。一般是存放在$ORACLE_HOME/admin/udump/$SID_ora_xxxx.trc

4:使用tkprof解析trace文件，便于阅读。

找到trace文件，执行：

tkprof  trace_file.trc output_file.txt;

然后cat output_file.txt |more 查看生成的trace报告。

tkprof使用方法：

tracefile：你要分析的trace文件 
outputfile：格式化后的文件 
explain=user/password@connectstring 
table=schema.tablename 
注1：这两个参数是一起使用的，通过连接数据库对在trace文件中出现的每条sql语句查看执行计划，并将之输出到outputfile中 
注2：该table必须是数据库中不存在的，如果存在会报错 
print=n：只列出最初N个sql执行语句 
insert=filename：会产生一个sql文件，运行此文件可将收集到的数据insert到数据库表中 
sys=no：过滤掉由sys执行的语句 
record=filename：可将非嵌套执行的sql语句过滤到指定的文件中去 
waits=yes|no：是否统计任何等待事件 
aggregate=yes|no：是否将相同sql语句的执行信息合计起来，默认为yes 
sort= option：设置排序选项，选项如下： 
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 

如下是我的trace文件：

TKPROF: Release 10.2.0.4.0 - Production on 星期五 11月 1 12:51:02 2013


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


Trace file: jtuser1_ora_25464.trc
Sort options: default


********************************************************************************
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
********************************************************************************


begin :id := sys.dbms_transaction.local_transaction_id; end;




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


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  
********************************************************************************


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.00          0          0          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           2


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  
********************************************************************************


select 'x' 
from
 dual




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


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  


Rows     Row Source Operation
-------  ---------------------------------------------------
      1  FAST DUAL  (cr=0 pr=0 pw=0 time=5 us)


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


begin
  if :enable = 0 then
    sys.dbms_output.disable;
  else
    sys.dbms_output.enable(:size);
  end if;
end;


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


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  
********************************************************************************


select count(*) 
from
 jtstatic.TBL_FL_FT_NEWUSERS




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.06       0.06          0       1638          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.06       0.06          0       1638          0           1


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  


Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=1638 pr=0 pw=0 time=65730 us)
  35338   BITMAP CONVERSION COUNT (cr=1638 pr=0 pw=0 time=176813 us)
  35338    BITMAP INDEX FAST FULL SCAN IDX_NU_DIM_DATE_FK (cr=1638 pr=0 pw=0 time=70780 us)(object id 56158)


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


SELECT * 
FROM
 jtstatic.TBL_FL_FT_NEWUSERS




call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.00          0          0          0           0


Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 68  
********************************************************************************


alter session set sql_trace false




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        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           0


Misses in library cache during parse: 0
Parsing user id: 68  






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


OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       13      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           8
Fetch        3      0.06       0.06          0       1638          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       28      0.06       0.06          0       1638          0          11


Misses in library cache during parse: 0




OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0


Misses in library cache during parse: 0


   13  user  SQL statements in session.
    0  internal SQL statements in session.
   13  SQL statements in session.
********************************************************************************
Trace file: jtuser1_ora_25464.trc
Trace file compatibility: 10.01.00
Sort options: default


       1  session in tracefile.
      13  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
      13  SQL statements in trace file.
       7  unique SQL statements in trace file.
     119  lines in trace file.
       5  elapsed seconds in trace file.