下面先生成一个执行计划:
SQL> select spid from v$process where addr = (select paddr from v$session where sid = (select sid from v$mystat where rownum = 1));
SPID
------------
3679
SQL> alter session set sql_trace = true;
会话已更改。
SQL> select * from t where object_id = 100;
OWNER
------------------------------
OBJECT_NAME
--------------------------------------------------------------------------------
SUBOBJECT_NAME OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
------------------------------ ---------- -------------- -------------------
CREATED LAST_DDL_TIME TIMESTAMP STATUS T G S
-------------- -------------- ------------------- ------- - - -
SYS
I_TYPED_VIEW1
100 100 INDEX
17-2月 -08 17-2月 -08 2008-02-17:01:50:58 VALID N N N
SQL> alter session set sql_trace = false;
会话已更改。
[oracle@linux udump]$ tkprof orcl_ora_3679.trc trace
TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:02:12 2011
Copyright (c) 1982, 2007, Oracle. All rights reserved.
[oracle@linux udump]$ cat trace.prf
TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:01:21 2011
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: orcl_ora_3679.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
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 0 27 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19 0.00 0.00 0 27 0 9
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=64 us)
1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=35 us)(object id 257)
********************************************************************************
select *
from
t where object_id = 100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 27 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 731 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 1 758 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 65
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T (cr=731 pr=1 pw=0 time=2532 us)
********************************************************************************
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: 65
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.01 0 27 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 731 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.01 1 758 0 1
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 0 27 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19 0.00 0.00 0 27 0 9
Misses in library cache during parse: 1
Misses in library cache during execute: 1
2 user SQL statements in session.
9 internal SQL statements in session.
11 SQL statements in session.
********************************************************************************
Trace file: orcl_ora_3679.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
9 internal SQL statements in trace file.
11 SQL statements in trace file.
3 unique SQL statements in trace file.
107 lines in trace file.
17 elapsed seconds in trace file.
下面来逐部解释这个trace文件:
TKPROF: Release 10.2.0.4.0 - Production on 星期六 10月 29 13:01:21 2011
Copyright (c) 1982, 2007, Oracle. All rights reserved.
Trace file: orcl_ora_3679.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
这是trace文件的头部,包含版本、时间以及报告中每一项的解释等信息。
********************************************************************************
select /*+ rule */ bucket_cnt, row_cnt, cache_cnt, null_cnt, timestamp#,
sample_size, minimum, maximum, distcnt, lowval, hival, density, col#,
spare1, spare2, avgcln
from
hist_head$ where obj#=:1 and intcol#=:2
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 0 27 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19 0.00 0.00 0 27 0 9
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: RULE
Parsing user id: SYS (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID HIST_HEAD$ (cr=3 pr=0 pw=0 time=64 us)
1 INDEX RANGE SCAN I_HH_OBJ#_INTCOL# (cr=2 pr=0 pw=0 time=35 us)(object id 257)
这些信息是解释sql用需要访问数据字典的查询,通常来讲不用太关注,在用tkprof生成trace文件的时候指定sys=no可以 忽略这些信息。
********************************************************************************
select *
from
t where object_id = 100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 27 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 731 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 1 758 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 65
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL T (cr=731 pr=1 pw=0 time=2532 us)
这是sql执行过程中的信息,通常来讲,每条sql都应该包含3个步骤:
分析(Parse):sql的分析阶段。
执行(Execute):sql的执行阶段。对于select语句,在许多情况下此阶段为空。对于update语句,此阶段将是执行所有工作的所在。
数据提取(Fetch):数据的提取阶段。对于select语句,大多数工作将在此阶段。对于update语句,将不显示任何工作。
横向的列除了call(调用)之外,还包括以下信息:
count:计数器,表示当前操作被执行了多少次。
cpu:表示当前操作消耗cpu的时间。(单位为秒)
elapsed:当前的操作一共消耗多少时间。(包括cpu事件和等待时间)
disk:当前操作的物理读。(磁盘I/O次数)
query:当前操作的一致性读方式读取的数据块数。(一致性读取,读undo,逻辑I/O次数。)
current:当前操作的current的方式读取的数据块数。(读前读取,读buffer_cache,逻辑I/O次数。)
rows:当前操作处理的数据记录数。在select查询中,该值出现在Fetch阶段。在更改操作中,该值出现在Execute阶段。
可以看这个sql被分析1次,执行1次,提取的2次。其中消耗cpu的时间是0.01秒,总耗时也是0.01秒。物理读取了1个块,一致性读取了758个数据块,没有发生current方式读取,供返回1行记录。
Misses in library cache during parse: 1 --shared pool中没有命中,这说明是一次硬解析,软分析这里为0。
Optimizer mode: ALL_ROWS --当前CBO优化器的模式。
Parsing user id: 65 --分析用户的id。
Rows:当前操作实际返回的记录数。
Row Source Operation:行源操作,表示当前操作的数据访问方式。
cr:consistent read 一致性方式读取的数据块,相当于query列上Fetch步骤的值。
pr:物理读取的数据块,相当于disk列上Fetch步骤的值。
pw:物理写。
time:当前操作执行的时间,us代表微妙。
如果在格式化trace文件的时候,加上explain=u1/u1还会看见sql的执行计划:
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 TABLE ACCESS MODE: ANALYZED (FULL) OF 'T' (TABLE)
********************************************************************************
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: 65
可以看见这个sql就是软解析的。
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.01 0 27 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 1 731 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.01 0.01 1 758 0 1
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 9 0.00 0.00 0 27 0 9
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 19 0.00 0.00 0 27 0 9
Misses in library cache during parse: 1
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS:对这个sql_trace期间所有非递归sql语句执行的信息统计汇总。
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS:对这个sql_trace期间所有递归sql语句执行的信息统计汇总。
递归sql:执行一条sql语句衍生出执行一些其他的sql,这些衍生出的sql就叫做递归sql。
2 user SQL statements in session.
9 internal SQL statements in session.
11 SQL statements in session.
********************************************************************************
Trace file: orcl_ora_3679.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
9 internal SQL statements in trace file.
11 SQL statements in trace file.
3 unique SQL statements in trace file.
107 lines in trace file.
17 elapsed seconds in trace file.
2 user SQL statements in session. --在这个trace中,用户sql有2条。
9 internal SQL statements in session. --在这个trace中,内部sql有9条。
11 SQL statements in session. --在这个trace中,总共11条sql。