一. SQL_TRACE

當SQL語句出現效能問題時，我們可以用SQL_TRACE來跟蹤SQL的執行情況，通過跟蹤，我們可以瞭解一條SQL或者PL/SQL包的執行情況，SQL_TRACE命令會將SQL執行的整個過程輸出到一個trace檔案中，我們可以讀這個trace 檔案來了解在這個SQL執行過程中Oracle 都做了哪些操作。

可以通過sql命令啟動SQL_TRACE，或者在初始化引數裡面。

SQL>alter session set sql_trace=true;

或者

SQL> alter database set sql_trace=true;

這兩條命令的區別：

在session

如果是在初始化檔案裡面設定，只需要在引數檔案裡新增一個sql_trace 引數即可。

示例：

1.確定當前的trace檔案。

1.1通過設定trace 檔案標識

SQL> alter session set tracefile_identifier='安慶懷寧';

會話已更改。

設定標識的目的就是方便我們查詢生成的trace檔案。我們只需要在trace目錄查詢檔名裡帶有標識的檔案即可。 在Oracle 10g中，SQL_TRACE生成的trace

到了11g，trace 預設路徑在：$ORACLE_BASE/diag/rdbms/orcl/orcl/trace目錄下.

1.2直接用如下SQL直接查出，當前的trace檔名。

/* Formatted on 2010/9/1 23:56:24 (QP5 v5.115.810.9015) */

SELECTd.VALUE

|| '/'

|| LOWER(RTRIM(i.INSTANCE,CHR(0)))

|| '_ora_'

|| p.spid

|| '.trc'

AS"trace_file_name"

FROM(SELECTp.spid

FROM

WHEREm.statistic# =1AND s.SID=m.SIDANDp.addr = s.paddr)p,

(SELECTt.INSTANCE

FROMv$thread t, v$parameter v

WHEREv.NAME='thread'

AND(v.VALUE=0ORt.thread# =TO_NUMBER(v.VALUE))) i,

(SELECTVALUE

FROMv$parameter

WHERENAME='user_dump_dest') d;

SQL> SELECTd.VALUE

2|| '/'

3|| LOWER (RTRIM (i.INSTANCE, CHR (0)))

4|| '_ora_'

5|| p.spid

6|| '.trc' as "trace_file_name"

7FROM (SELECT p.spid

8FROM v$mystat m, v$session s, v$process p

9WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,

10(SELECT t.INSTANCE

11FROM v$thread t, v$parameter v

12WHERE v.NAME = 'thread'

13AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,

14(SELECT VALUE

15FROM v$parameter

16WHERE NAME = 'user_dump_dest') d;

trace_file_name

--------------------------------------------------------------------------------

d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048.trc

2.啟動SQL_TRACE

SQL> alter session set sql_trace=true;

會話已更改。

3.進行相關事務操作

SQL> select * from t;

4.關閉SQL_TRACE

SQL> alter session set sql_trace=false;

會話已更改。

注意，這裡是顯示的關閉SQL_TRACE，在session級別，也可以直接退出SQLPLUS來終止SQL_TRACE。

二． TKPROF 工具

Oracle 官網的資料：

Using Application Tracing Tools

SQL_TRACE 生成最原始的trace檔案的可讀性比較差，所以通常我們使用tkprof 工具來處理trace檔案。 Tkprof 工具是Oracle 自帶的一個工具，用於處理原始的trace檔案，它的作用主要是合併彙總trace檔案中的一些項，規範化檔案的格式，使檔案更具有可讀性。

注意：tkprof 工具只能用在處理SQL_TRACE和10046事件產生的trace，其他事件如10053不能處理。

以前也整理過一篇文章：

使用 Tkprof 分析 ORACLE 跟蹤檔案

剛才看了一些，也是比較粗糙，不詳細，重新在整理一下。 Tkprof 是系統級別的，直接在系統下執行即可。先看一下tkprof的幫助文件：

C:/Users/Administrator.DavidDai>tkprof

Usage: tkprof tracefile outputfile [explain= ] [table= ]

[print= ] [insert= ] [sys= ] [sort= ]

table=schema.tablenameUse 'schema.tablename' with 'explain=' option.

explain=user/passwordConnect to ORACLE and issue EXPLAIN PLAN.

print=integerList only the first 'integer' SQL statements.

aggregate=yes|no

insert=filenameList SQL statements and data inside INSERT statements.

sys=noTKPROF does not list SQL statements run as user SYS.

record=filenameRecord non-recursive statements found in the trace file.

waits=yes|noRecord summary for any wait events found in the trace file.

sort=optionSet of zero or more of the following sort options:

prscntnumber of times parse was called

prscpucpu time parsing

prselaelapsed time parsing

prsdsknumber of disk reads during parse

prsqrynumber of buffers for consistent read during parse

prscunumber of buffers for current read during parse

prsmisnumber of misses in library cache during parse

execntnumber of execute was called

execpucpu time spent executing

exeelaelapsed time executing

exedsknumber of disk reads during execute

exeqrynumber of buffers for consistent read during execute

execunumber of buffers for current read during execute

exerownumber of rows processed during execute

exemisnumber of library cache misses during execute

fchcntnumber of times fetch was called

fchcpucpu time spent fetching

fchelaelapsed time fetching

fchdsknumber of disk reads during fetch

fchqrynumber of buffers for consistent read during fetch

fchcunumber of buffers for current read during fetch

fchrownumber of rows fetched

useriduserid of user that parsed the cursor

這個幫助對tkprof工具的引數做了說明。

2.1explain=user/password

在trace檔案中輸入SQL的執行計劃，需要注意的是，如果不使用explain，在trace 檔案中我們看到的是SQL實際的執行路勁。 如果使用了explain，tkprof在trace檔案中不但輸入SQL的實際執行路徑，還會生成該SQL的執行計劃。

2.2 sys=no

如果設定為yes，在trace 檔案中將輸入所有的SYS使用者的操作，也包含使用者SQL語句引發的遞迴SQL。

如果為no，則不輸出這些資訊。

不過預設情況下是yes，實際上設定為no後，trace檔案具有更佳的可讀性，因此一般在用tkprof工具時都手工的把該引數設定為no。

2.3 aggregate=yes|no

預設情況下，tkprof工具將所有相同的SQL在輸入檔案中做合併，如果設定為no，則分別列出每個SQL的資訊。一般合併後看起來比較簡潔，如果需要檢視每一個SQL單獨的資訊，可以把aggregate設定為no。

2.4 檢視第一節中生成的trace檔案

C:/Users/Administrator.DavidDai>cd d:/app/administrator/diag/rdbms/orcl/orcl/trace

C:/Users/Administrator.DavidDai>D:

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>tkprof orcl_ora_3048_安慶懷寧.trc 安徽安慶懷寧.txt sys=no

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.All rights reserved.

d:/app/Administrator/diag/rdbms/orcl/orcl/trace>

生成的 安徽安慶懷寧.txt檔案內容如下：

TKPROF: Release 11.2.0.1.0 - Development on 星期四 9月 2 00:22:03 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.All rights reserved.

Trace file: orcl_ora_3048_安慶懷寧.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

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

# 以上檔案頭資訊描述了tkprof的版本資訊，以及報告中一些列的含義

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS#非遞迴SQL語句

callcountcpuelapseddiskquerycurrentrows

------- -------------- ---------- ---------- ---------- ---------- ----------

Parse40.010.030000

Execute50.000.000002

Fetch670.000.0001400980

------- -------------- ---------- ---------- ---------- ---------- ----------

total760.010.0301400982

Misses in library cache during parse: 2 #shared pool 中沒有命令，說明做了2次硬解析，軟解析此處為0

Oracle SQL的硬解析和軟解析

Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS#遞迴SQL語句

callcountcpuelapseddiskquerycurrentrows

------- -------------- ---------- ---------- ---------- ---------- ----------

Parse50.000.000000

Execute570.000.000000

Fetch1130.000.0001760110

------- -------------- ---------- ---------- ---------- ---------- ----------

total1750.000.0001760110

Misses in library cache during parse: 0

5userSQL statements in session.

57internal SQL statements in session.

62SQL statements in session.

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

Trace file: orcl_ora_3048_安慶懷寧.trc

Trace file compatibility: 11.1.0.7

Sort options: default

3sessions in tracefile.

10userSQL statements in trace file.

114internal SQL statements in trace file.

62SQL statements in trace file.

9unique SQL statements in trace file.

613lines in trace file.

27elapsed seconds in trace file.

2.5 檢視trace 檔案

在2.4中，我們看到了tkprof生成的報告，這個報告是一個彙總的結果集，如果想確切的知道SQL 語句的每一步執行是如果操作的，就需要分析原始的trace檔案。 這個trace 雖然沒有tkprof工具處理之後易讀，但是卻能夠清楚的知道SQL在那個點做了什麼，以及SQL是如何工作的，這對與理解SQL語句的執行過程非常有用。

直接開啟 orcl_ora_3048_安慶懷寧.trc 檔案：

Trace file d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_3048_安慶懷寧.trc

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

Windows NT Version V6.1

CPU: 2 - type 586, 2 Physical Cores

Process Affinity: 0x0x00000000

Memory (Avail/Total): Ph:1559M/4095M, Ph+PgF:4170M/8188M, VA:2881M/4095M

Instance name: orcl

Redo thread mounted by this instance: 1

Oracle process number: 29

Windows thread id: 3048, image: ORACLE.EXE (SHAD)

*** 2010-09-01 23:45:51.877

*** SESSION ID:(267.996) 2010-09-01 23:45:51.877

*** CLIENT ID:() 2010-09-01 23:45:51.877

*** SERVICE NAME:(SYS$USERS) 2010-09-01 23:45:51.877

*** MODULE NAME:(sqlplus.exe) 2010-09-01 23:45:51.877

*** ACTION NAME:() 2010-09-01 23:45:51.877

……..

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

PARSING IN CURSOR #12 len=493 dep=1 uid=0 oct=3 lid=0 tim=488541717777 hv=2584065658 ad='b1dad758' sqlid='1gu8t96d0bdmu'

select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)

END OF STMT

PARSE #12:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541717773

EXEC #12:c=0,e=80,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=488541718176

FETCH #12:c=0,e=127,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=2035254952,tim=488541718359

STAT #12 id=1 cnt=1 pid=0 pos=1 obj=0 op='MERGE JOIN OUTER (cr=4 pr=0 pw=0 time=0 us cost=2 size=189 card=1)'

STAT #12 id=2 cnt=1 pid=1 pos=1 obj=4 op='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=137 card=1)'

STAT #12 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=0 us cost=1 size=0 card=1)'

STAT #12 id=4 cnt=0 pid=1 pos=2 obj=0 op='BUFFER SORT (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

STAT #12 id=5 cnt=0 pid=4 pos=1 obj=429 op='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=1 pr=0 pw=0 time=0 us cost=0 size=52 card=1)'

STAT #12 id=6 cnt=0 pid=5 pos=1 obj=430 op='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'