Oracle SQL Trace 和10046 事件

一. 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級別設定，只對當前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) */

SELECT d.VALUE

|| '/'

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

|| '_ora_'

|| p.spid

|| '.trc'

AS "trace_file_name"

FROM (SELECT p.spid

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

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

(SELECT t.INSTANCE

FROM v$thread t, v$parameter v

WHERE v.NAME = 'thread'

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

(SELECT VALUE

FROM v$parameter

WHERE NAME = 'user_dump_dest') d;

SQL> SELECT d.VALUE

2 || '/'

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

4 || '_ora_'

5 || p.spid

6 || '.trc' as "trace_file_name"

7 FROM (SELECT p.spid

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

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

10 (SELECT t.INSTANCE

11 FROM v$thread t, v$parameter v

12 WHERE v.NAME = 'thread'

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

14 (SELECT VALUE

15 FROM v$parameter

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

http://download.oracle.com/docs/cd/E11882_01/server.112/e10821/sqltrace.htm#PFGRF010

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

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

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

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

aggregate=yes|no

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

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

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

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

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

prscnt number of times parse was called

prscpu cpu time parsing

prsela elapsed time parsing

prsdsk number of disk reads during parse

prsqry number of buffers for consistent read during parse

prscu number of buffers for current read during parse

prsmis number of misses in library cache during parse

execnt number of execute was called

execpu cpu time spent executing

exeela elapsed time executing

exedsk number of disk reads during execute

exeqry number of buffers for consistent read during execute

execu number of buffers for current read during execute

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

fchela elapsed time fetching

fchdsk number of disk reads during fetch

fchqry number of buffers for consistent read during fetch

fchcu number of buffers for current read during fetch

fchrow number of rows fetched

userid userid of user that parsed the cursor

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

2.1 explain=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 ALL NON-RECURSIVE STATEMENTS #非遞迴SQL語句

call count cpu elapsed disk query current rows

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

Parse 4 0.01 0.03 0 0 0 0

Execute 5 0.00 0.00 0 0 0 2

Fetch 67 0.00 0.00 0 140 0 980

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

total 76 0.01 0.03 0 140 0 982

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 ALL RECURSIVE STATEMENTS #遞迴SQL語句

call count cpu elapsed disk query current rows

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

Parse 5 0.00 0.00 0 0 0 0

Execute 57 0.00 0.00 0 0 0 0

Fetch 113 0.00 0.00 0 176 0 110

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

total 175 0.00 0.00 0 176 0 110

Misses in library cache during parse: 0

5 user SQL statements in session.

57 internal SQL statements in session.

62 SQL statements in session.

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

Trace file: orcl_ora_3048_安慶懷寧.trc

Trace file compatibility: 11.1.0.7

Sort options: default

3 sessions in tracefile.

10 user SQL statements in trace file.

114 internal SQL statements in trace file.

62 SQL statements in trace file.

9 unique SQL statements in trace file.

613 lines in trace file.

27 elapsed 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;

SID SERIAL#

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

267 996

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

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

Oracle SQL Trace 和10046 事件

相關文章