在Oracle中利用SQL_TRACE跟踪SQL的执行

当你在执行一条SQL语句非常慢的时候,你是不是想问Oracle怎么执行这条语句的呢? Oracle提供的SQL_TRACE工具可以让你知道你执行的SQL究竟做了什么.执行的过程会被输出到trace文件中。 下面用例子来跟踪一个SQL语句的执行情况: SQL create table t as select ro

当你在执行一条SQL语句非常慢的时候,你是不是想问Oracle怎么执行这条语句的呢?
Oracle提供的SQL_TRACE工具可以让你知道你执行的SQL究竟做了什么.执行的过程会被输出到trace文件中。

下面用例子来跟踪一个SQL语句的执行情况:

SQL> create table t as select rownum as id,object_name from dba_objects;


Table created.
SQL> create index t_ind on t(id);
Index created.
SQL> alter session set tracefile_identifier='mysession';
Session altered.
生成的trace文件的路径是$Oracle_BASE/admin/SID/udump目录.
上面的语句是让生产trace文件名包括mysession,如本例中在

D:\Oracle\product\10.2.0\admin\orcl\udump生成了orcl_ora_5732_mysession.trc
SQL> alter session set sql_trace=true;
Session altered.
SQL> select * from t where id=123;
ID     OBJECT_NAME
123    I_ACCESS1
SQL> alter session set sql_trace=false;
Session altered.

一般来讲生成的trace文件比较难读,可以用tkprof来生成一个更可读的文件.
注意tkprof是Oracle带的一个命令行工具,不是SQLPLUS命令.

在另外一个命令行中进入D:\Oracle\product\10.2.0\admin\orcl\udump目录
D:\Oracle\product\10.2.0\admin\orcl\udump>tkprof orcl_ora_5732_mysession.trc orcl_ora_5732_mysession.txt
TKPROF: Release 10.2.0.1.0 - Production on Fri Sep 14 16:59:12 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.

打开 orcl_ora_5732_mysession.txt文件,可以看到执行SQL的信息:
select *
from
t where id=123
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.30          0          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.30          0          6          0           1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61 
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID T (cr=4 pr=0 pw=0 time=86 us)
      1   INDEX RANGE SCAN T_IND (cr=3 pr=0 pw=0 time=67 us)(object id 57205)

对于每一条SQL语句,都包含3个步骤:
Parse:SQL的分析阶段.
Execute:SQL的执行阶段.
Fetch:数据提取阶段.(对于一次SQL操作,Fetch可能多次)
横向的标题头为:
ount:当前的操作执行的次数.
cpu:当前操作消耗的CPU时间(秒).
elapsed:当前操作消耗的时间(CPU时间加等待时间).
disk:磁盘的IO次数.
query:当前操作的一致性读取的数据块数.
current:前操作的current读取的数据块数(通常在update操作是发生).
rows:处理的记录行数.

Misses in library cache during parse是指是不是重用了执行计划,如果同一条SQL语句第二次执行,
其值为零,这里是1,表示在共享池里没有这一条SQL的执行计划,发生了一次硬解析.
Optimizer:优化器模式.
Parsing user id:分析的用户ID.
Row Source Operation部分包含的实际消耗的资源.
cr:一致性读取的数据块,相当于Fetch的query.
pr:物理读, 相当于Fetch的disk.
pw:物理写. 
time:当前操作的执行时间.

同时我们在trace文件里还会发现对系统表的访问的SQL,这就是通常说的递归SQL.

还可以利用10046事件来跟踪SQL,它比SQL_TRACE提供更详细的信息.它有LEVEL 1,4,8,12四个级别.
其中Level 1 相当于 SQL_TRACE.下面是10046使用的例子
SQL> alter session set events '10046 trace name context forever,level 4';
Session altered.
.... some SQL statements
SQL> alter session set events '10046 trace name context off';
Session altered.