oracle 工具：tkprof

 

 

    1 定義

          用於分析oracle追蹤檔案並且可按需產生一個更加清晰合理的輸出結果的可執行工具

 

    2 喜好設定

F:\>tkprofUsage: 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

              注釋：
              ① fchela這是個比較有用的sort選項，在產生的.prf檔案將把最消耗時間的sql放在最前面顯示
              ② sys=no 以sys身份執行的sql不會被顯示，增加可讀性

 

    3 tkprof輸出檔案中各列的含義

call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------

          注釋：
          ㈠ call：
             每次sql的處理都分成3個部分
             ① parse：將sql語句轉成執行計畫，包括檢查許可權、表及其關聯對象是否存在等
             ② execute：由sql引擎執行，因事務類型不同而異
             ③ fetch：這步只有select語句被執行，buffer cache是主戰場
          ㈡ count：
             這條sql被parse、execute和fetch的次數
          ㈢ cpu：該sql語句所消耗的cpu的時間（單位：s）
          ㈣ elapsed：該sql語句在各個階段的執行時間
          ㈤ disk：
             從磁碟上的資料檔案中物理讀取的塊的數量
          ㈥ query：
             在一致性讀的模式下，各階段所獲得的buffer的數量。一致性模式下，buffer是用於給一個長查詢提供一致性
             讀的快照
          ㈦ current：
             在當前讀的模式下，各階段所獲得的buffer的數量。
          ㈧ rows：
             所有的sql返回的記錄數目，但不包括子查詢返回的記錄。
             對於select語句，返回是在fetch這步
             對於DML語句，返回是在execute這步

 

    4 tkprof的使用步驟

        ⑴ 在執行個體層級上設定timed_statistic=true
        SQL> show parameter timed_statistic
       
        NAME_COL_PLUS_SHOW_P TYPE                   VALUE_COL_PLUS_SHOW_
        -------------------- ---------------------- --------------------
        timed_statistics     boolean                TRUE
        ⑵ 使用各種工具得到想要查看session的trc檔案
        ⑶ udump路徑找到產生的trc檔案
        ⑷ 對trc檔案進行tkprof分析
           tkprof tracefile outfile [options]
           注意：這條語句後面沒有分號結尾！！

 

    5案例

18:32:55 hr@ORCL (^ω^) alter session set events '10046 trace name context forever,level 12';會話已更改。18:34:00 hr@ORCL (^ω^) select count(*) from t;  COUNT(*)----------         218:34:00 hr@ORCL (^ω^) update t1 set tname='think high' where id=1;已更新 1 行。18:34:30 hr@ORCL (^ω^) alter session set events '10046 trace name context off';會話已更改。18:34:55 hr@ORCL (^ω^) exitD:\oracle\product\10.2.0\admin\orcl\udump>tkprof orcl_ora_6004.trc C:\Users\Administrator\tkprof_starting.txt sys=no waits=yes sort=fcheTKPROF: Release 10.2.0.1.0 - Production on 星期日 9月 23 19:19:13 2012Copyright (c) 1982, 2005, Oracle.  All rights reserved.

    這個tkprof檔案最後的一部分如下：

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse       11      0.03       0.16          0          0          0           0Execute     41      0.07       0.22          0          0          0           0Fetch       48      0.03       0.12          3        118          0          50------- ------  -------- ---------- ---------- ---------- ----------  ----------total      100      0.14       0.51          3        118          0          50Misses in library cache during parse: 11Misses in library cache during execute: 11Elapsed times include waiting on following events:  Event waited on                             Times   Max. Wait  Total Waited  ----------------------------------------   Waited  ----------  ------------  db file sequential read                         3        0.02          0.05    3  user  SQL statements in session.   41  internal SQL statements in session.   44  SQL statements in session.********************************************************************************Trace file: orcl_ora_6004.trcTrace file compatibility: 10.01.00Sort options: fchela         1  session in tracefile.       3  user  SQL statements in trace file.      41  internal SQL statements in trace file.      44  SQL statements in trace file.      14  unique SQL statements in trace file.     902  lines in trace file.      55  elapsed seconds in trace file.

          注釋：
          ① 這個session共有44條sql語句在裡面，對於遞迴的語句一共分析了41次
          ② 計算hit ratio
             logical reads=consistent gets+ db block gets
             consistent gets=query列的execute+query列的fetch
             db block gets=current列的execute+current列的fetch
             因此，logical reads=118+0+0+0=118
             physical reads=disk列，即：3
             所以，hit ratio=L/（L+P)=97.5%
          ③ 還有一對參數非常重要，fetch的次數以及取得的記錄的行數，一般來說，以儘可能少的fetch來取得儘可能多的記錄數
             ，也就是，fetch的值要遠遠小於取得的記錄數才好。從上面這個例子可知，fetch了48，rows 50，這表明
             有些記錄是通過好幾次的fetch才得到的。這個session的有些sql是需要最佳化的。
          ④ 從query列的parse可以看出從row cache裡讀取的資料

 

    這個tkprof檔案中兩個sql語句摘入如下：

********************************************************************************select count(*) from tcall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.01       0.06          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.01          6          7          0           1------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.01       0.08          6          7          0           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 55  Rows     Row Source Operation-------  ---------------------------------------------------      1  SORT AGGREGATE (cr=7 pr=6 pw=0 time=15493 us)      2   TABLE ACCESS FULL T (cr=7 pr=6 pw=0 time=15449 us)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  db file sequential read                         1        0.01          0.01  db file scattered read                          1        0.00          0.00  SQL*Net message from client                     2        0.00          0.00

            注釋：
            從上面的輸出可以看到，這條語句訪問了7個塊來找到需要select的記錄，返回1條記錄。
            這個查詢parse了1次，而且是hard parse 1次。

            select語句主要看fetch這一行

********************************************************************************update t1 set tname='think high' where id=1call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.03          0          5          2           1Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        2      0.00       0.03          0          1          1           1Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: 55  Rows     Row Source Operation-------  ---------------------------------------------------      1  UPDATE  T1 (cr=1 pr=0 pw=0 time=31186 us)      1   INDEX UNIQUE SCAN INDEX_T1 (cr=1 pr=0 pw=0 time=23 us)(object id 54498)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        0.00          0.00

            注釋：
            這條語句訪問了5個block來找到需要的update的記錄，在執行update的時候只訪問了2個，一共更新了1條記錄

            DML語句主要看execute這一行