【轉】 sql_trace

前言：
sql_trace 是我在工作中經常要用到的調優工具，
相比較statspack 我更願意用這個工具。
因為資料庫慢原因的85%以上是由於sql問題造成的，
statspack沒有sql的執行計劃。顯示沒有它直觀，方便，對想要針對性不強，

1，介紹
資料庫調優需要經常會用到的工具，可以很精確地跟抓取相關session正在執行的sql。再通過tkprof分析出來sql的執行計劃等相關資訊，從而判斷那些sql語句存在問題。

統計如下資訊（摘字官方文件）：
Parse, execute, and fetch counts
CPU and elapsed times
Physical reads and logical reads
Number of rows processed
Misses on the library cache
Username under which each parse occurred
Each commit and rollback

2，使用
使用前需要注意的地方
1,初始化引數
timed_statistics=true  允許sql trace 和其他的一些動態效能檢視收集與時間（cpu，elapsed）有關的引數。一定要開啟，不然相關資訊不會被收集。這是一個動態的引數，也可以在session級別設定。
SQL>alter session set titimed_statistics=true
2,MAX_DUMP_FILE_SIZE
跟蹤檔案的大小的限制，如果跟蹤資訊較多可以設定成unlimited。可以是KB,MB單位，9I開始預設為unlimited
這是一個動態的引數，也可以在session級別設定。
SQL>alter system set max_dump_file_size=300
SQL>alter system set max_dump_file_size=unlimited
3,USER_DUMP_DEST
指定跟蹤檔案的路徑,預設路徑實在$ORACLE_BASE/admin/ORA_SID/udump
這是一個動態的引數，也可以在session級別設定。
SQL>alter system set user_dump_dest=/oracle/trace

資料庫級別
設定slq_trace引數為true會對整個例項進行跟蹤，包括所有程式：使用者程式和後臺程式，會造成比較嚴重的效能問題，生產環境一定要慎用。
SQL>alter system set sql_trace=true;

Session級別：
當前會話：
SQL>alter session set sql_trace=true;
SQL>alter session set sql_trace=false;
其他會話：
通過oracle提供的系統包 DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION來實現。
SQL>execute dbms_system.set_sql_trace_in_session(sid,serial#,true);
SQL>execute dbms_system.set_sql_trace_in_session(sid,serial#,false);
注：
1，sid,serial#從v$session檢視中獲得。
2，DBMS_SYSTEM包裡還可以對其他使用者的引數（如：timed_statistics,max_dump_file）進行設定，在這不做介紹了，很少用到。想了解dbms_system裡的程式包可以desc dbms_system看一下。
得到trace檔案後我們要用tkprof他進行格式化,通過sql語句快速定位到相應的trace檔案
Tkprof
tkprof 的目的是將sql trace 生成的跟蹤檔案轉換成使用者可以理解的格式
格式：
tkprof tracefile outputfile [optional | parameters ]
引數和選項（這裡只介紹最常用的，也是最實用的）
explain=user/password 執行explain命令將結果放在SQL trace的輸出檔案中
sys=[yes/no] 確定系統是否列出由sys使用者產生或重調的sql語句
sort=sort_option 按照指定的方法對sql trace的輸出檔案進行降序排序
sort_option 選項
prscnt  按解析次數排序
prscpu  按解析所花cpu時間排序
prsela  按解析所經歷的時間排序
prsdsk  按解析時物理的讀操作的次數排序
prsqry  按解析時以一致模式讀取資料塊的次數排序
prscu   按解析時以當前讀取資料塊的次數進行排序
execnt  按執行次數排序
execpu  按執行時花的cpu時間排序
exeela  按執行所經歷的時間排序
exedsk  按執行時物理讀操作的次數排序
exeqry  按執行時以一致模式讀取資料塊的次數排序
execu   按執行時以當前模式讀取資料塊的次數排序
exerow  按執行時處理的記錄的次數進行排序
exemis  按執行時庫緩衝區的錯誤排序
fchcnt  按返回資料的次數進行排序
fchcpu  按返回資料cpu所花時間排序
fchela  按返回資料所經歷的時間排序
fchdsk  按返回資料時的物理讀操作的次數排序
fchqry  按返回資料時一致模式讀取資料塊的次數排序
fchcu   按返回資料時當前模式讀取資料塊的次數排序
fchrow  按返回資料時處理的資料數量排序
注：
這些排序中我經常用到的是fchdsk,fckchela ,fchqry.因為有問題的sql一般都是大的查詢造成的，當然更新，插入，刪除時也會存在全表掃描，這就需要:exedsk,exeqry,exeela等選項。根據具體情況具體分析。
Cpu時間和Elapsed時間都是以秒為單位，而且兩個值基本上一樣，但我比較常用elapsed，他是反映的使用者相應時間，從執行sql到使用者得到結果的時間，會更實際些。

tkprof輸出檔案各列的含義：（理解下面的含義對我們快速定位問題很有幫助）
parse:
將sql語句轉換成執行計劃，包括檢查是否有正確的授權，需要到得表，列及其他引用到得物件是否存在，這些資訊分別存在v$librarycache.v$rowcache..
execute
oracle實際執行的語句，如：insert,update,delete,這些會修改資料，對於select操作，這部只是確定選擇的行數。
fetch
返回查詢獲得的行數，只有執行select會被收集。
Count
這個語句被parse，execute，fetch的次數的統計
Cpu
這個語句所有的parse，execute，fetch所用的cpu總的時間，以秒為單位。如果TIMED_STATISTICS 關閉的話，值為0。
Elapsed
這個語句所有的parse，execute，fetch所消耗的總的時間，以秒為單位。如果TIMED_STATISTICS 關閉的話，值為0。
Disk
這個語句所有的parse，execute，fetch從磁碟上的資料檔案中讀取的資料塊的數量
Query
在一致性讀的模式下，這個語句所有的parse，execute，fetch所獲取的buffer數量（這部分是從記憶體讀取的也就是邏輯讀取的，相當於執行計劃裡的consistent gets）
Current
在current模式下，這個語句所有的parse，execute，fetch所獲取的buffer數量，一般是current模式下發生的delect,insert,update的操作都會獲取buffer。
Rows
語句返回的行數，不包括子查詢中返回的記錄數目。對於select語句，返回在fetch這步，對於insert，delete，update操作，返回記錄是在execute這步。

3，分析：
我一般的思路步驟是：
1,現找磁碟多的sq l(sort= fchdsk )，意味著全表掃描
2，找執行時間長的(sort= fchela)，意味著sql可能寫的不好或磁碟，邏輯讀較多
3，找出一致性讀較多的(sort= fchqry)，當表不是很大的時候（可能全部快取住了），沒有發生磁碟讀，但不意味著不需要建立索引，或者sql需要優化
4,找出當前模式從緩衝區獲得資料的數量(sort=exedsk,exeela,exeqry)，這些主要集中在dml語句裡的操作，看是否有必要優化sql或建立索引
之所以排序是為了在sql很多的時候快速定位sql，如果sql比較少的話就沒必要排序了，
但我們要有分析問題的思路。

4，舉例：
我自己建立了一個表
create table t1 (id int);
begin
for v1 in 1..1000000 loop
insert into t1 values(v1);
end loop
commit;
end;

下面是sql_trace所抓到得sql.

不正常狀態
*******************************************************************************
select *
from  t1
where id=1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.00       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch       10      1.23       9.64       4387       9062          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       20      1.23       9.64       4387       9062          0           5

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 258  (WH)
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL T1
Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      1   TABLE ACCESS (FULL) OF 'T1'

*******************************************************************************
首先這是一個select語句，
它走了全部掃描，
磁碟讀（4387）和邏輯讀（9062）都很多
執行了5次（Execute）,分析了5次（Parse），一共用了將近10秒（elapsed）。
我只是選擇表的一行的資料的結果，就發生這麼大的成本。很顯然是全表掃描的結果造成的。

正常狀態：
在做跟蹤前 我為這個表建立了一個索引
Create index t1 on t1(id);
*******************************************************************************
select *
from t1
where id=1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1     0.01       0.00          0          0          0           0
Execute      5      0.00       0.00          0          0          0           0
Fetch        5      0.00       0.02          3         20          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       11     0.01       0.03          3         20          0           5
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 258  (WH)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  INDEX RANGE SCAN T1 (object id 9491829)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      1   INDEX (RANGE SCAN) OF 'T1' (NON-UNIQUE)

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

同樣的語句
它走了索引，
物理讀3 這個3其實是開始讀索引時需要第一次讀入的。以後執行就沒有了。
邏輯讀20（平均這個sql一次4個邏輯讀）
同樣執行了5次（Execute）
分析了1次（Parse） 執行次數越多，分析次數越少越好
一共只用了0.03秒（elapsed）。

可以看出前後很大的差距。


5，注意：
電腦學習網首發

執行計劃走了索引，不一定在實際應用中就走了，我們一定要結合磁碟讀，一致性讀，執行時間，返回行數等資訊來確定是否真正走了索引，可能存在索引失效的現象。關於索引為什麼失效可以看我另外一個文章，寫的比較全面：
http://www.cnscn.org/htm_data/586/0904/46107.html