sql_trace 命令會將sql執行的整個過程輸出到一個trace檔案中，然後透過閱讀這個trace檔案瞭解整個sql執行過程中sql究竟做了些什麼。

sql_trace 命令可以在會話級別設定（session），也可以在例項（system）級別設定

alter session set sql_trace=true; （會話級別）

alter system set sql_trace=true; （例項級別）

通常我們會在 session級別設定sql_trace ，不建議在 system級別設定，因為這樣的代價太高了。

同時，設定生成的trace檔名，預設trace檔案儲存在 udump 中

C:\>sqlplus / as sysdba

SQL*Plus: Release 10.2.0.1.0 - Production on 星期二 5月 15 14:18:07 2012

連線到:
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options

SQL>
SQL> show parameter user_dump;

NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string C:\ORACLE\PRODUCT\10.2.0\ADMIN \ORCL\UDUMP

例子如下：

SQL> alter session set tracefile_identifier='mytest'; // 設定 trace檔案的名字

會話已更改。

SQL> alter session set sql_trace=true; // 設定會話級別的sql trace

會話已更改。

SQL> select * from scott.t where rownum<200 ;

SQL> alter session set sql_trace=false; // 終止sql_trace ，也可以直接退出SQLPLUS

話已更改。

然後到udump目錄下，找到了新生成的trace檔案

C:\oracle\product\10.2.0\admin\orcl\udump 路徑下的： orcl_ora_2480_mytest.trc 檔案

一般生成的 trace 檔案可讀性比較差，我們通常會用tkprof工具來處理這個trace檔案

C:\>tkprof C:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2480_mytest.trc out.txt

TKPROF: Release 10.2.0.1.0 - Production on 星期二 5月 15 14:06:41 2012

而新生成的out.txt 就在C:\ 目錄下，以下就是 out.txt 內容

TKPROF: Release 10.2.0.1.0 - Production on 星期二 5月 15 14:06:41 2012

Trace file: C:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2480_mytest.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.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
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************

select *
from
scott.t where rownum<200

call     count       cpu    elapsed       disk      query    current        rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse        1      0.00       0.03          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       15      0.00       0.00          0        244          0         199
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total       17      0.00       0.04          0        244          0         199

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

Rows     Row Source Operation
------- ---------------------------------------------------
    199 COUNT STOPKEY (cr=244 pr=0 pw=0 time=2366 us)
    199   TABLE ACCESS FULL T (cr=244 pr=0 pw=0 time=1562 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: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse        2      0.00       0.03          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch       15      0.00       0.00          0        244          0         199
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total       20      0.00       0.04          0        244          0         199

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        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

    3 user SQL statements in session.
    0 internal SQL statements in session.
    3 SQL statements in session.
********************************************************************************
Trace file: C:\oracle\product\10.2.0\admin\orcl\udump\orcl_ora_2480_mytest.trc
Trace file compatibility: 10.01.00
Sort options: default

       0 session in tracefile.
       3 user SQL statements in trace file.
       0 internal SQL statements in trace file.
       3 SQL statements in trace file.
       3 unique SQL statements in trace file.
      44 lines in trace file.
      26 elapsed seconds in trace file.

========================================

========================================

註解：

count    = number of times OCI procedure was executed

                 表示當前的操作被執行了多少次

cpu      = cpu time in seconds executing

                當前操作消耗了cpu的時間（單位秒）

elapsed = elapsed time in seconds executing

                  當前的操作一共用時多少（包括cpu時間和等待時間）

disk     = number of physical reads of buffers from disk

                當前操作的物理讀（磁碟i/o次數）

query    = number of buffers gotten for consistent read

                 當前操作的一致性讀方式讀取的資料塊數

                （通常是查詢使用的是方式）

current = number of buffers gotten in current mode (usually for update)

                   當前操作的current的方式讀取的資料塊數

                  （通常是修改資料使用的方式）

rows     = number of rows processed by the fetch or execute call
                 （當前操作處理的資料記錄數）

sql_trace 及 tkprof 工具

相關文章