Tkprof工具詳解一（轉載）
阿新 • • 發佈：2018-03-10
depth ber 官方 Go ble 不可 _id sys 避免
PARSING IN CURSOR 部分：
PARSE, EXEC, FETCH部分：
STAT部分：
在數據庫生成的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：當前行源的數據訪問操作
Tkprof工具詳解一（轉載）