目錄

• 主要說明
• 關鍵選項
• 用法示例

• 對SCOTT開啟跟蹤
• 執行一條SQL語句
• 對SCOTT關閉跟蹤
• tkprof分析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)

☆〖本人水平有限，文中如有錯誤還請留言批評指正！〗☆