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

当你在执行一条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可能多次)

横向的标题头为:

count:当前的操作执行的次数.

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.