正文 另一篇博文總結了關於SQL TRACE工具的使用方式，但是產生的trace文件格式閱讀起來並不是十分友好，為了更好的分析trace文件，Oracle也自帶了一個格式化工具 tkprof 。 tkprof 工具用於處理原始的trace文件，合併彙總trace文件當中一些項目值，然後進行格式化，這 ...
正文
另一篇博文總結了關於SQL TRACE工具的使用方式，但是產生的trace文件格式閱讀起來並不是十分友好，為了更好的分析trace文件，Oracle也自帶了一個格式化工具tkprof。tkprof工具用於處理原始的trace文件，合併彙總trace文件當中一些項目值，然後進行格式化，這樣就使得trace文件的可讀性更好。
關於tkprof的詳細說明可以參考官方文檔：Understanding SQL Trace and TKPROF
關於trace文件的生成可以參考另一篇博文：Oracle 11g R2性能優化 SQL TRACE
主要說明
tkprof命令位於 $ORACLE_HOME/bin/路徑下，通過命令tkprof直接獲取相關選項參數：
$ tkprof
Usage: tkprof tracefile outputfile [explain= ] [table= ]
[print= ] [insert= ] [sys= ] [sort= ]
關鍵選項
tracefile
需要格式化的trace文件outputfile
格式化完成後的輸出文件explain=
通過給定方式連接資料庫，併為每條語句生成執行計劃sort=
指定排序鍵來展示SQL語句
其他選項如下：
table=schema.tablename Use 'schema.tablename' with 'explain=' option. -- 指定PLAN_TABLE生成執行計劃，預設為系統的PLAN_TABLE
explain=user/password Connect to ORACLE and issue EXPLAIN PLAN.
print=integer List only the first 'integer' SQL statements. -- 顯示指定數目的SQL語句
aggregate=yes|no -- 指定是否對重覆SQL語句信息合併，預設yes合併，如果指定為no，對重覆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用戶執行的語句
record=filename Record non-recursive statements found in the trace file. -- 指定生成不包含遞歸語句的SQL語句文件
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:
-- 1、解析調用期間執行排序
prscnt number of times parse was called -- 解析次數
prscpu cpu time parsing -- 解析消耗CPU時間
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 -- 解析時庫緩存區未命中次數
-- 2、執行調用期間執行排序
execnt number of execute was called -- 執行次數
execpu cpu time spent executing -- 執行時消耗CPU時間
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 -- 執行時庫緩衝區未命中次數
-- 3、提取調用期間執行排序
fchcnt number of times fetch was called -- 提取數據次數
fchcpu cpu time spent fetching -- 提取時消耗CPU時間
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 -- 按游標解析時的userid排序
關於tkprof工具更詳細的用法可以參考Oracle MOS文檔：TKProf Interpretation (9i and above) (文檔 ID 760786.1)
用法示例
對SCOTT開啟跟蹤
$ sqlplus scott/tiger
SCOTT@dbabd> alter session set tracefile_identifier = 'SCOTT';
Session altered.
SCOTT@dbabd> exec dbms_session.session_trace_enable(true, true, 'all_executions');
PL/SQL procedure successfully completed.執行一條SQL語句
SCOTT@dbabd> select * from emp;
EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ---------- --------------- ---------- ------------------- ---------- ---------- ----------
7369 SMITH CLERK 7902 1980-12-17 00:00:00 800 20
7499 ALLEN SALESMAN 7698 1981-02-20 00:00:00 1600 300 30
7521 WARD SALESMAN 7698 1981-02-22 00:00:00 1250 500 30
7566 JONES MANAGER 7839 1981-04-02 00:00:00 2975 20
7654 MARTIN SALESMAN 7698 1981-09-28 00:00:00 1250 1400 30
7698 BLAKE MANAGER 7839 1981-05-01 00:00:00 2850 30
7782 CLARK MANAGER 7839 1981-06-09 00:00:00 2450 10
7788 SCOTT ANALYST 7566 1987-04-19 00:00:00 3000 20
7839 KING PRESIDENT 1981-11-17 00:00:00 5000 10
7844 TURNER SALESMAN 7698 1981-09-08 00:00:00 1500 0 30
7876 ADAMS CLERK 7788 1987-05-23 00:00:00 1100 20
7900 JAMES CLERK 7698 1981-12-03 00:00:00 950 30
7902 FORD ANALYST 7566 1981-12-03 00:00:00 3000 20
7934 MILLER CLERK 7782 1982-01-23 00:00:00 1300 10
14 rows selected.對SCOTT關閉跟蹤
SCOTT@dbabd> exec dbms_session.session_trace_disable();
PL/SQL procedure successfully completed.tkprof分析trace文件
執行如下命令生成格式化文件：
$ tkprof /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_SCOTT.trc /data/app/scott_trace.log explain=scott/tiger aggregate=yes sys=no waits=yes sort=fchela
查看tkprof生成文件：
$ cat /data/app/scott_trace.log
-- 開頭概要部分，基本信息說明，包括tkprof版本、trace文件路徑、排序選項和報告參數說明
TKPROF: Release 11.2.0.4.0 - Development on Thu Jan 17 17:41:04 2019
Copyright (c) 1982, 2011, Oracle and/or its affiliates. All rights reserved.
Trace file: /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_SCOTT.trc
Sort options: fchela
********************************************************************************
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
********************************************************************************
-- 跟蹤的SQL語句文本、SQL ID和執行計劃HASH
SQL ID: a2dk8bdn0ujx7 Plan Hash: 3956160932
select *
from
emp
-- SQL執行的統計信息
/*
call:調用類型
count:調用執行次數
cpu:需要的CPU時間(單位:秒)
elapsed:需要消耗的時間(單位:秒)
disk:發生物理讀次數
query:發生一致讀次數
current:發生當前讀次數
rows:獲取的行數
*/
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 7 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 7 0 14
Misses in library cache during parse: 1 -- 庫緩存沒有命中數，說明是硬解析
Optimizer mode: ALL_ROWS -- 優化器模式
Parsing user id: 83 (SCOTT) -- 解析用戶
Number of plan statistics captured: 1 -- 執行計劃統計信息獲取數
-- SQL語句實際執行消耗的資源信息
/*
Rows:操作實際返回記錄數
Row Source Operation:當前行操作的訪問方式
cr:一致性讀的數據塊，對應query的Fetch值
pr:物理讀的數據塊，對應disk的Fetch值
pw:物理寫的數據塊
time:執行時間
cost:優化器執行成本
size:處理的位元組數
card:處理的記錄數
*/
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
14 14 14 TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=211 us cost=3 size=532 card=14)
-- 指定explain選項輸出的執行計劃
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT MODE: ALL_ROWS
14 TABLE ACCESS MODE: ANALYZED (FULL) OF 'EMP' (TABLE)
-- 指定選項waits=yes選項輸出的等待事件信息統計
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 128.00 128.00
********************************************************************************
SQL ID: bnqn0qyvy59qf Plan Hash: 0
BEGIN dbms_session.session_trace_enable(true, true, 'all_executions'); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 61 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 61 0 1
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 68.47 68.47
********************************************************************************
SQL ID: 23d3sap7cask4 Plan Hash: 0
BEGIN dbms_session.session_trace_disable(); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83 (SCOTT)
********************************************************************************
-- 開啟跟蹤期間所有非遞歸SQL語句執行信息統計彙總
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.01 0.01 0 0 0 0
Execute 3 0.00 0.00 0 61 0 2
Fetch 2 0.00 0.00 0 7 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 7 0.01 0.01 0 68 0 16
Misses in library cache during parse: 2
Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 128.00 196.48
-- 開啟跟蹤期間所有遞歸SQL語句執行信息統計彙總
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 23 0.00 0.00 0 0 0 0
Fetch 37 0.00 0.00 2 82 0 28
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 60 0.00 0.00 2 82 0 28
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.00 0.00
-- 所有分析的SQL語句彙總統計
3 user SQL statements in session.
13 internal SQL statements in session.
16 SQL statements in session.
1 statement EXPLAINed in this session.
********************************************************************************
Trace file: /data/app/oracle/diag/rdbms/dbabd/dbabd/trace/dbabd_ora_18629_SCOTT.trc
Trace file compatibility: 11.1.0.7
Sort options: fchela
1 session in tracefile.
3 user SQL statements in trace file.
13 internal SQL statements in trace file.
16 SQL statements in trace file.
16 unique SQL statements in trace file.
1 SQL statements EXPLAINed using schema:
SCOTT.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
411 lines in trace file.
196 elapsed seconds in trace file.
總結
以上梳理了關於tkprof工具的簡單用法，經過它格式化之後的trace文件更具有可讀性，真實地統計了SQL語句在執行過程當中資源的消耗。但是它提供的是彙總後的統計信息，如果需要瞭解SQL語句執行時每個步驟的資源消耗情況可以通過閱讀原始的trace文件，這裡不再進行深入討論了。SQL性能優化博大精深，涉及的知識面廣泛，也經常涉及Oracle底層運行機制和操作系統底層實現，需要自己學習與提高的地方還有很多。
參考
https://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94981
TKProf Interpretation (9i and above) (文檔 ID 760786.1)
☆〖本人水平有限，文中如有錯誤還請留言批評指正！〗☆
