一.SQL_TRACE

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

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

SQL>altersessionset sql_trace=true;

或者

SQL> alterdatabaseset sql_trace=true;

這兩條命令的區別：

在session級別設定，只對當前session進行跟蹤，在例項級別，會對例項上所有的SQL做跟蹤，這種方式跟蹤的SQL太多，代價是非常大的，所有很少用。

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

示例：

1.確定當前的trace檔案。

1.1透過設定trace檔案標識

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

會話已更改。

設定標識的目的就是方便我們查詢生成的trace檔案。我們只需要在trace目錄查詢檔名裡帶有標識的檔案即可。在Oracle 10g中，SQL_TRACE生成的trace檔案預設路勁是$ORACLE_BASE/admin/SID/udump.

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

FROMv$mystatm,v$session s,v$processp

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

(SELECTt.INSTANCE

FROMv$threadt,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跟蹤檔案

http://blog.csdn.net/tianlesoftware/archive/2010/05/29/5632003.aspx

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

C:/Users/Administrator.DavidDai>tkprof

Usage

tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ]

例:1.tkprof tracefile outfile [explain=user/password] [options...];

例:2.tkprof uat_ora_14936.trc trace.txt sort=(prsdsk,exedsk,fchdsk) print=10 explain=apps/apps table=apps.temp_plan_table_a insert=storea.sql sys=no

tkprof引數介紹

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

用於指定在將執行計劃寫進輸出檔案之前，TKPROF用於臨時存放執行計劃所用表的屬主和名稱，需要和explain引數一起使用。

explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.

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

只列出輸出檔案中的第一個INTEGER的SQL語句，若忽略，則TKPROF將列出所有跟蹤的SQL語句

aggregate=yes|no

若使用者指定AGGREGATE=NO，TKPROF將不會對相同SQL文字的多個使用者進行彙總。

insert=filename List SQL statements and data inside INSERT statements.

SQL指令碼的一種，用於將跟蹤檔案的動機資訊儲存到資料庫中。

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

於啟動或禁止將使用者SYS所釋出的SQL語句列表到輸出檔案之中，也包括遞迴SQL(為執行使用者的SQL語句，ORACLE還必須執行一些附加語句)語句在內。預設為YES。

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

對於跟蹤檔案中的所用非遞迴SQL語句，TKPROF將以指定的名稱來建立某個SQL指令碼。用於對跟蹤檔案中的使用者時間進行重放。

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

記錄trace檔案中所有等待事件的摘要。

sort=option Set of zero or more of the following sort options:

在將被跟蹤的SQL語句列表輸出到跟蹤檔案之前，先將其按照指定排序選項的降序關係對其進行排序；

若指定了多種排序選項，那麼根據排序選項所指定值的和的降序關係對其進行排序；

若忽略此引數，那麼TKPROF將按照使用次序把語句列表到輸出檔案中，具體選項說明如下：

　　prscnt number of times parse was called語句解析的數目。

　　prscpu cpu time parsing語句解析所佔用的CPU時間。

　　prsela elapsed time parsing語句解析所佔用的時間（總是大於或等於CPU時間）；

　　prsdsk number of disk reads during parse語句解析期間，從磁碟進行物理讀取的數目。

prsqry number of buffers for consistent read during parse語句解析期間，一致模式塊讀取（CONSISTENT MODE BLOCK READ）的數目。

prscu number of buffers for current read during parse語句解析期間，當前模式讀取（CURRENT MODE BLOCK READ）的數目。

　　prsmis number of misses in library cache during parse語句解析期間，庫快取失敗的數

目。

　　execnt number of execute was called語句執行的數目。

　　execpu cpu time spent executing語句執行所佔用的CPU時間。

　　exeela elapsed time executing語句執行所佔用的時間（總是大於或等於CPU時間）。

　　exedsk number of disk reads during execute語句執行期間，從磁碟進行物理讀取的數目。

exeqry number of buffers for consistent read during execute語句執行期間，一致模式塊讀取（CONSISTENT MODE BLOCK READ）的數目。

execu number of buffers for current read during execute語句執行期間，當前模式讀取（CURRENT MODE BLOCK READ）的數目。

　　exerow number of rows processed during execute語句執行期間，所處理的語句行數。

　　exemis number of library cache misses during execute語句執行期間，庫快取失敗的數目。

　　fchcnt number of times fetch was called取資料的數目。

　　fchcpu cpu time spent fetching取資料所佔用的CPU時間。

　　fchela elapsed time fetching取資料所佔用的時間（總是大於或等於CPU時間）。

　　fchdsk number of disk reads during fetch取資料期間，從磁碟進行物理讀取的數目。

fchqry number of buffers for consistent read during fetch取資料期間，一致模式塊讀取（CONSISTENT MODE BLOCK READ）的數目。

fchcu number of buffers for current read during fetch取資料期間，當前模式讀取（CURRENT MODE BLOCK READ）的數目。

fchrow number of rows fetched所獲取的行數。

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

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

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

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

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 ALLNON-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的硬解析和軟解析

http://blog.csdn.net/tianlesoftware/archive/2010/04/08/5458896.aspx

Misses in library cache during execute: 1

OVERALL TOTALS FOR ALLRECURSIVE 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 ct=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 bj=0 p='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 bj=4 p='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 bj=3 p='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 bj=0 p='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 bj=429 p='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 bj=430 p='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=1 pr=0 pw=0 time=0 us cost=0 size=0 card=1)'

CLOSE #12:c=0,e=11607,dep=1,type=3,tim=488541730026

…………

這個檔案的可讀性要差很多。對這裡面的一些引數做些說明：

PARSING IN CURSOR部分：

Len:被解析SQL的長度

Dep:產生遞迴SQL的深度

Uid：user id

Otc: Oracle command type命令的型別

Lid:私有使用者id

Tim：時間戳

Hv：hash value

Ad：SQL address

PARSE,EXEC,FETCH部分

C:消耗的CPU time

E：elapsed time操作的用時

P: physical reads物理讀的次數

Cr: consistent reads一致性方式讀取的資料塊

Cu：current方式讀取的資料塊

Mis：cursor misss in cache硬分析次數

R: -rows處理的行數

Dep: depth遞迴SQL的深度

Og：optimizer goal最佳化器模式

Tim：timestamp時間戳

STATS部分：

Id:執行計劃的行源號

Cnt：當前行源返回的行數

Pid：當前行源號的父號

Pos：執行計劃中的位置

Obj：當前操作的物件id（如果當前行原始一個物件的話）

Op：當前行源的資料訪問操作

三．10046事件

Oracle的事件很多。具體參考blog：

Oracle跟蹤事件set event

http://blog.csdn.net/tianlesoftware/archive/2009/12/13/4977827.aspx

10046事件主要用來跟蹤SQL語句，它並不是ORACLE官方提供給使用者的命令，在官方文件上也找不到事件的說明資訊。但是用的卻比較多，因為10046事件獲取SQL的資訊比SQL_TRACE更多。更有利於我們對SQL的判斷。

10046事件按照收集資訊內容，可以分成4個級別：

Level 1：等同於SQL_TRACE的功能

Level 4：在Level 1的基礎上增加收集繫結變數的資訊

Level 8：在Level 1的基礎上增加等待事件的資訊

Level 12：等同於Level 4+Level 8,即同時收集繫結變數資訊和等待事件資訊。

3.1對當前session使用10046事件

SQL>alter session set events ‘10046 trace name context forever, level 12’;--啟動10046事件

執行相關事務

SQL>alter session set events ‘10046 trace name context off’;--關閉10046事件

該事件收集的資訊也是放在trace檔案中，檢視trace檔案的方法，參考第二節：TKPROF工具。

3.2對其他的會話進行跟蹤

之前說的都是對當前session進行跟蹤，在生產環境中，可能需要對其他session進行跟蹤，有如下2種方法：

3.2.1用SQL_TRACE跟蹤

SQL> select sid,serial# from v$session where SID=267;

SIDSERIAL#

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

267996

SQL> execute dbms_system.set_sql_trace_in_session(267,996,true);--啟動SQL_TRACE

PL/SQL過程已成功完成。

SQL> execute dbms_system.set_sql_trace_in_session(267,996,false);--關閉SQL_TRACE

PL/SQL過程已成功完成。

3.2.2使用10046事件跟蹤

SQL> exec dbms_monitor.session_trace_enable(267,996,waits=>true,binds=>true);--啟動trace

PL/SQL過程已成功完成。

SQL> exec dbms_monitor.session_trace_disable(267,996);--關閉trace

PL/SQL過程已成功完成。

注意：

如果一條SQL語句中包含了透過DBLINK進行的資料操作，我們想對這條SQL進行trace跟蹤，在本地只能夠trace到本地執行的SQL資訊，而對於遠端的SQL語句，由於它執行在遠端的資料庫上，我們要獲得它的資訊，需要到遠端的資料庫上，找到執行這條SQL語句的session，然後對它做Trace。另外，這條SQL語句的執行計劃也只能從遠端資料庫上捕獲到。

總之，當SQL語句操作出現效能問題時，我們可以用SQL_TRACE或者10046事件進行跟蹤是最合適的。如果是資料庫整體效能下降，就需要使用statspack或者AWR對資料庫進行分析。

Oracle AWR介紹

http://blog.csdn.net/tianlesoftware/archive/2009/10/17/4682300.aspx

SQL TRACE和TKPROF,10046的使用步驟

相關文章