sql_trace 及 tkprof 工具

xfhuangfu發表於2015-07-04
SQL
   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
Copyright (c) 1982, 2005, Oracle.  All rights reserved.

連線到:
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
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
 
 
而新生成的out.txt 就在C:\ 目錄下 ， 以下就是 out.txt 內容
 
 
TKPROF: Release 10.2.0.1.0 - Production on 星期二 5月 15 14:06:41 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
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
                 （當前操作處理的資料記錄數）
            

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28373936/viewspace-1722289/，如需轉載，請註明出處，否則將追究法律責任。

相關文章