在生产环境中，当数据库运行异常缓慢的时候，DBA同学们都会想冲进数据库内部看看sql到底如何运行，为何语句执行的如此缓慢？在我的生产环境中，经常有多表关联查询语句运行缓慢，多数是I/O等待的问题，因而我第一步会去看sql的执行计划是否出现了问题，其次就会用到sql trace工具来跟踪下sql的实际运行情况！
一：使用sql_trace
1:产生select语句的trace文件，一般会使用tracefile_identifier给trace文件起一个标识性的名称，便于查找
2：使用tkprof工具对产生的trace文件进行过滤，抽取有用的信息，默认的trace文件输出太多信息！
sys=no代表不输出trace文件中所有sys用户的操作，包含用户sql语句引起的递归sql，使输出变的简洁；
aggragate=yes代表相同的sql语句在输入文件中做合并，使输出变的简洁；
[oracle@dg53 udump]$ tkprof dg53_ora_10498_hr_trace01.trc /home/oracle/trace01.log aggregate=yes sys=no explain=hr/hr
[oracle@dg53 udump]$ wc -l dg53_ora_10498_hr_trace01.trc
1097 dg53_ora_10498_hr_trace01.trc
[oracle@dg53 udump]$ wc -l /home/oracle/trace01.log
137 /home/oracle/trace01.log
[oracle@dg53 ~]$ cat trace01.log
TKPROF: Release 10.2.0.1.0 - Production on Fri Jun 8 12:06:23 2012
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: dg53_ora_10498_hr_trace01.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
********************************************************************************
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.01 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.01 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 (HR)
********************************************************************************
select salary,last_name
from
employees where employee_id=100
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.01 2 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.04 2 2 0 1
Misses in library cache during parse: 1 (表示该sql语句执行了硬解析，未在库缓存中命中)
Optimizer mode: ALL_ROWS (CBO的模式，表示尽可能快的输出全部的结果集，oltp系统分页条件下普遍使用first_rows)
Parsing user id: 55 (HR)
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID EMPLOYEES (cr=2 pr=2 pw=0 time=18516 us)
1 INDEX UNIQUE SCAN EMP_EMP_ID_PK (cr=1 pr=1 pw=0 time=11715 us)(object id
51859)
Rows Execution Plan (因为在使用tkprof分析trace文件的时候使用了explain参数，所以有执行计划输出)
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'EMPLOYEES'
(TABLE)
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'EMP_EMP_ID_PK' (INDEX
(UNIQUE))
********************************************************************************
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: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 (HR)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.02 0 0 0 0
Execute 3 0.00 0.01 0 0 0 0
Fetch 2 0.00 0.01 2 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.00 0.05 2 2 0 1
Misses in library cache during parse: 2
Misses in library cache during execute: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 21 0.01 0.02 0 0 0 0
Execute 122 0.03 0.03 0 0 0 0
Fetch 173 0.01 0.16 18 419 0 633
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 316 0.06 0.22 18 419 0 633
Misses in library cache during parse: 15
Misses in library cache during execute: 15
3 user SQL statements in session.
122 internal SQL statements in session.
125 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: dg53_ora_10498_hr_trace01.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
122 internal SQL statements in trace file.
125 SQL statements in trace file.
18 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
HR.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
1097 lines in trace file.
38 elapsed seconds in trace file.