SQL_TRACE與tkprof分析

一. 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 sql命令啟動SQL_TRACE

SQL> alter session set sql_trace=true;
Session altered.

2 透過設定trace 檔案標識

SQL> alter session set tracefile_identifier='andy';
Session altered.

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

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

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

SQL> select * from v$diag_info where name like 'Default%';

INST_ID NAME
---------- ----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
1 Default Trace File
/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc

4. 進行相關事務操作
SQL> select * from t;

5. 關閉SQL_TRACE
SQL> alter session set sql_trace=false;

會話已更改。

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

——————————————————————————————————————

6. 檢視trace 檔案（原始檢視方式，即不使用tkprof工具檢視）

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

直接開啟 /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc檔案：

T[oracle@11g ~]$ vi /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc

Trace file /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /home/oracle/app/oracle/product/11.2.0/dbhome_1
System name: Linux
Node name: 11g
Release: 2.6.32-573.el6.x86_64
Version: #1 SMP Thu Jul 23 15:44:03 UTC 2015
Machine: x86_64
Oracle process number: 19
Unix process pid: 24020, image: oracle@11g (TNS V1-V3)

。。。。。省略輸出

*** 2014-11-17 08:06:08.981
CLOSE #1:c=0,e=14,dep=0,type=1,tim=1416229568981377
=====================
PARSING IN CURSOR #1 len=23 dep=0 uid=0 oct=3 lid=0 tim=1416229568981763 hv=665675061 ad='87d2dfb0' sqlid='ckyh1gcmuut9p'
select * from dba_users
END OF STMT
PARSE #1:c=0,e=291,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981762
EXEC #1:c=0,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981961
FETCH #1:c=4000,e=3231,p=0,cr=52,cu=0,mis=0,r=1,dep=0,og=1,plh=3422547789,tim=1416229568985261
FETCH #1:c=0,e=67,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229568985934
FETCH #1:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229569004724
FETCH #1:c=0,e=83,p=0,cr=1,cu=0,mis=0,r=4,dep=0,og=1,plh=3422547789,tim=1416229569022491
STAT #1 id=1 cnt=35 pid=0 pos=1 obj=0 op='HASH JOIN (cr=54 pr=0 pw=0 time=0 us cost=26 size=2664 card=12)'
STAT #1 id=2 cnt=35 pid=1 pos=1 obj=0 op='HASH JOIN (cr=49 pr=0 pw=0 time=0 us cost=24 size=2436 card=12)'
STAT #1 id=3 cnt=35 pid=2 pos=1 obj=0 op='HASH JOIN (cr=34 pr=0 pw=0 time=34 us cost=18 size=2316 card=12)'
STAT #1 id=4 cnt=35 pid=3 pos=1 obj=0 op='HASH JOIN OUTER (cr=19 pr=0 pw=0 time=68 us cost=13 size=2196 card=12)'
STAT #1 id=5 cnt=35 pid=4 pos=1 obj=0 op='HASH JOIN (cr=16 pr=0 pw=0 time=0 us cost=10 size=1740 card=12)'
STAT #1 id=6 cnt=35 pid=5 pos=1 obj=0 op='HASH JOIN (cr=13 pr=0 pw=0 time=136 us cost=8 size=1620 card=12)'
STAT #1 id=7 cnt=2 pid=6 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=6 pr=0 pw=0 time=1 us cost=4 size=26 card=1)'
STAT #1 id=8 cnt=1 pid=7 pos=1 obj=280 op='TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=13 card=1)'
STAT #1 id=9 cnt=2 pid=7 pos=2 obj=0 op='BUFFER SORT (cr=3 pr=0 pw=0 time=1 us cost=2 size=13 card=1)'
STAT #1 id=10 cnt=2 pid=9 pos=1 obj=280 op='TABLE ACCESS FULL PROFILE$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=13 card=1)'
STAT #1 id=11 cnt=35 pid=6 pos=2 obj=22 op='TABLE ACCESS FULL USER$ (cr=7 pr=0 pw=0 time=102 us cost=3 size=3597 card=33)'
STAT #1 id=12 cnt=2 pid=5 pos=2 obj=281 op='TABLE ACCESS FULL PROFNAME$ (cr=3 pr=0 pw=0 time=1 us cost=2 size=10 card=1)'
STAT #1 id=13 cnt=2 pid=4 pos=2 obj=297 op='TABLE ACCESS FULL RESOURCE_GROUP_MAPPING$ (cr=3 pr=0 pw=0 time=0 us cost=2 size=38 card=1)'
STAT #1 id=14 cnt=8 pid=3 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=15 pr=0 pw=0 time=105 us cost=5 size=80 card=8)'
STAT #1 id=15 cnt=8 pid=2 pos=2 obj=16 op='TABLE ACCESS FULL TS$ (cr=15 pr=0 pw=0 time=14 us cost=5 size=80 card=8)'
STAT #1 id=16 cnt=9 pid=1 pos=2 obj=292 op='TABLE ACCESS FULL USER_ASTATUS_MAP (cr=5 pr=0 pw=0 time=0 us cost=2 size=171 card=9)'

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

PARSING IN CURSOR 部分： PARSE,EXEC,FETCH 部分 STATS 部分：

Len: 被解析SQL的長度 C: 消耗的CPU time Id: 執行計劃的行源號 
Dep: 產生遞迴SQL的深度 E：elapsed time 操作的用時 Cnt：當前行源返回的行數

Uid：user id P: physical reads 物理讀的次數 Pid：當前行源號的父號

Otc: Oracle command type 命令的型別 Cr: consistent reads 一致性方式讀取的資料塊 Pos：執行計劃中的位置

Lid: 私有使用者id Cu：current 方式讀取的資料塊 Obj：當前操作的物件id（如果當前行原始一個物件的話）

Tim：時間戳 Mis：cursor misss in cache 硬分析次數 Op：當前行源的資料訪問操作

Hv： hash value R: -rows 處理的行數

Ad：SQL address Dep: depth 遞迴SQL的深度

Og： optimizer goal 最佳化器模式

Tim：timestamp時間戳

二． TKPROF 工具

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

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

Tkprof 是系統級別的，直接在系統下執行即可。先看一下tkprof的幫助文件：

[oracle@11g ~]$ 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 用tkprof工具檢視中生成的trace檔案

[oracle@11g ~]$ tkprof /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc andy.txt sys=no

[oracle@11g ~]$ vi andy.txt

TKPROF: Release 11.2.0.1.0 - Development on Mon Nov 17 08:25:36 2014
Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved.
Trace file: /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.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 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.03 0 54 0 36
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11 0.00 0.03 0 54 0 36

Misses in library cache during parse: 0

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 #shared pool 命中，說明做了0次硬解析。

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.

Misses in library cache during parse: 0

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

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace file: /home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
71 lines in trace file.
1719 elapsed seconds in trace file.

ok,結束。