Tkprof工具詳解一

 

注明：一些文章是從別人的博客中轉載過來的，方便自己以后查閱：
在數據庫生成的oracle trace文件中，可讀性是比較差的，此時可使用tkprof工具來格式化trace文件，tkprof是一個命令行工具，作用就是把原始的跟蹤trace文件作為輸入，然后格式化一個可讀性比較好的文本文件。

在下面的例子中，輸入文件是 ora11g_ora_3918.trc，輸出文件是test.log

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42

oracle @ root : ~ / diag / rdbms / orcl / ora11g / trace > tkprof ora11g_ora_3918 . trc test . log   TKPROF : Release 11.2.0.1.0 - Development on Sat Jun 22 11 : 38 : 40 2013   Copyright ( c ) 1982 , 2009 , Oracle and / or its affiliates .    All rights reserved .   下面我們來了解一下 tkprof的參數，直接敲 tkprof命令即可查看參數： oracle @ root : ~ / diag / rdbms / orcl / ora11g / trace > 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

explain：參數格式為explain=username/password@server_name 或者explain=username/password，這個參數是通過執行explain plan語句來做到的，在trace文件中找到每個sql語句，提供一個執行計划。一般不是必要情況，指定這個參數並不可取，一旦指定了無效的信息，在輸出的文件就會出現error。

table：table參數只和explain參數一起使用，用來指定某個表被explain plan語句使用來生成執行計划，通常盡量避免使用table參數，這里就不詳細說明不常用的參數了，大家想要了解的話，可以查看oracle的官方聯機文檔。

print：參數用來限制輸出文件生成的sql語句的數量，默認是無限制的。eg：只輸出10個sql語句，則參數指定print=10，一般和sort參數一起使用才具有一定的意義。

insert：生成sql腳本，腳本可以用來把數據存儲到數據庫中。eg：insert=load_data.sql 。

sys：參數執行sys用戶下運行的sql語句是否寫入到輸出文件，默認為yes。可設置為no，避免輸出不必要的信息，這個看情況而定吧。

sort：排序的意思，指定輸出文件里面的sql語句的順序，默認是trace源文件里面的sql順序。你可以指定根據cpu時間，物理讀的塊數，調用次數等進行排序，eg：sort=elapsed,disk   —多個排序用逗號隔開。

aggregate：參數指定是否合並相同的sql，默認為yes，設置為no，輸出文件就會列出每個sql的消耗情況等信息。

用得比較多的一般是sys和aggregate參數。

下面我們來簡單分析一下經過tkprof工具格式化處理過的trace文件：

 

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84

oracle @ root : ~ / diag / rdbms / orcl / ora11g / trace > more mount_open . log --頭部內容，這里可以看到 trace源文件， sort參數等信息 TKPROF : Release 11.2.0.1.0 - Development on Fri Jun 21 14 : 00 : 51 2013   Copyright ( c ) 1982 , 2009 , Oracle and / or its affiliates .    All rights reserved .   Trace file : / opt / oracle / diag / rdbms / orcl / ora11g / trace / ora11g_ora_14009 . 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 * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *   頭部內容下面的部分就是針對每個 sql的信息： sql文本，統計信息，解析信息，執行計划，等待事件等。 * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *   SQL ID : 0cmnx32jn5wsp Plan Hash : 1876228229 CREATE INDEX I_OBJ # ON CLUSTER C_OBJ# PCTFREE 10 INITRANS 2 MAXTRANS 255    STORAGE (    INITIAL 64K NEXT 1024K MINEXTENTS 1 MAXEXTENTS 2147483645    PCTINCREASE 0 OBJNO 3 EXTENTS ( FILE 1 BLOCK 168 ) )   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          0        0.00        0.00            0            0            0            0 -- -- -- - -- -- --    -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- --    -- -- -- -- -- total          2        0.00        0.00            0            0            0            0   count：執行的數據庫調用數量，也就是當前操作執行的次數 cpu：處理數據花費的 cpu時間，單位是秒 elapsed：當前操作花費的總用時，包括 cpu時間和等待時間，單位是秒 disk：物理讀的數據庫數量 query：當前操作的一致性模式讀取的數據塊數，通常是查詢 current：當前操作讀取的數據塊數，通常是修改數據，比如 insert ， update， delete等語句所使用的。 rows：當前操作處理的數據行數   Misses in library cache during parse : 1 -- -- --表示 shared pool沒有命中，這是一次硬分析，軟分析這里為 0 Optimizer mode : CHOOSE    -- -- -當前的優化模式 Parsing user id : SYS    ( recursive depth : 1 )    -- -當前處理的對象   Rows     Row Source Operation -- -- -- -    -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -- -        0    INDEX BUILD UNIQUE I_OBJ # (cr=0 pr=0 pw=0 time=0 us)(object id 0)        0    SORT CREATE INDEX ( cr = 0 pr = 0 pw = 0 time = 0 us cost = 0 size = 0 card = 0 )        0      TABLE ACCESS FULL C_OBJ # (cr=0 pr=0 pw=0 time=0 us)   rows：表示當前操作返回的數據條數 Row Source Operation：行源操作，表示當前數據的訪問方式 cr：一致性方式讀取的數據塊數，相當於 query列上的 fetch步驟的值 pr：物理讀的數據塊，相當於 disk列上的 fetch步驟的值 pw：物理寫入磁盤的數據塊數 time：以微秒表示的總的消逝時間 cost：操作的評估開銷 size：操作返回的預估數據量，單位是字節 card：操作返回的語句行數   注意：這些值除了 card之外，都是累計的。 * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * *   此外 trace文件有很多內容值得探索，這里基礎就不體現了。   下面來看一下原始 sql_trace生成的原始 trace文件，沒有經過 tkprof處理 PARSING IN CURSOR #4 len=35 dep=0 uid=85 oct=3 lid=85 tim=1371272962082555 hv=4042069092 ad='7e2769c0' sqlid='6xxmr xrsfu534 ' select * from t where object_id=345 END OF STMT PARSE #4:c=0,e=2120,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082553 EXEC #4:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962082705 FETCH #4:c=0,e=5486,p=5,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3745387144,tim=1371272962088298 FETCH #4:c=0,e=30,p=0,cr=1,cu=0,mis=0,r=0,dep=0,og=1,plh=3745387144,tim=1371272962094265 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=73517 op=' TABLE ACCESS BY INDEX ROWID T ( cr = 4 pr = 5 pw = 0 time = 0 us cost = 2 size = 29 card = 1 ) ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=73518 op=' INDEX RANGE SCAN BIN $ 3x4G / ATIcRfgQKjAgpEWgw == $ 0 ( cr = 3 pr = 5 pw = 0 time = 0 us cost = 1 size = 0 card = 1 )' * * * 2013 - 06 - 15 01 : 09 : 36.832 CLOSE #4:c=0,e=40,dep=0,type=0,tim=1371272976832430

 oracle會首先對這條sql語句作分析，並且有一個游標號：CURSOR #4，這個號在整個trace文件中不是唯一的，當一條sql語句執行結束后，這個號被重用
我們還可以看到這條sql語句被分析了一次，執行了一次，fetch了2次，STAT#4是對這條sql語句執行過程中的資源消耗統計，trace文件中信息的輸出順序就是sql語句執行的順序，通過這些順序，就可以知道sql語句是如果執行的

PARSING IN CURSOR 部分：
len：被分析sql的長度
dep：產生遞歸sql的深度
uid：userid
otc：oracle command type命令的類型
lid：私有的用戶id
tim：時間戳
hv：hash value
ad：sql address

PARSE, EXEC, FETCH部分：
c：消耗的cpu time
e：elapsed time操作用時
p：physical reads物理讀的次數
cr：consistent reads一致性方式讀取的數據塊數
cu：current方式讀取的數據塊數
mis：cursor miss in cache 硬分析的次數
r：rows處理的行數
dep：depth遞歸sql的深度
og：optimizer goal優化器模式
tim：timestamp 時間戳

STAT部分：
id：執行計划的行源號
cnt：當前行源返回的行數
pid：當前行源號的父號
pos：當前操作的對象id，如果當前行原始一個對象的話
op：當前行源的數據訪問操作