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.