【TKPROF】使用TKPROF格式化TRACE輸出之“解剖麻雀”
《【SQL_TRACE】SQL優化及性能診斷好幫手》http://space.itpub.net/519536/viewspace-616240中簡單的提到了使用TKPROF工具格式化SQL_TRACE的輸出信息的方法，并沒有對輸出的內容做比較清楚的描述，通過這個小文兒，展示一下TKPROF對trace文件格式化的魅力，這里只給出具體輸出信息含義的描述，不展示真實的性能診斷案例。
1.與之上次使用到的SQL_TRACE功能相比，我們這次將使用更高級的trace命令（10046）來做演示。我們先啟用“高級”的10046事件生成一份待格式化的trace文件
1）連接到普通用戶sec
sys@ora10g> conn sec/sec
Connected.
2）先將timed_statistics參數設置為true，這樣可以使TKPROF工具能提供更多的有意義的信息，方便性能診斷
sec@ora10g> alter session set timed_statistics=true;
Session altered.
3）“高級”之所在，我們這里啟用10046的level 12對當前會話進行跟蹤。
（1）在此，給出10046各level的解釋參考：
level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)
等同于標準的SQL_TRACE=TRUE；
level 4 to enable SQL_TRACE and also capture bind variable values in the trace file
啟用SQL_TRACE，并捕捉跟蹤文件中的綁定變量；
level 8 to enable SQL_TRACE and also capture wait events into the trace file
啟用SQL_TRACE，并捕捉跟蹤文件中的等待事件；
level 12 to enable standard SQL_TRACE and also capture bind variables and wait events
啟用SQL_TRACE，并捕捉跟蹤文件中的綁定變量和等待事件（捕獲信息能力最強）。
（2）對當前會話啟用level 12的跟蹤：
sec@ora10g> alter session set events '10046 trace name context forever, level 12';
Session altered.
（3）【補充】如果想使用這種高級方法對其他的會話進行跟蹤的話，可以使用如下的SQL語句開啟和關閉：
開啟：execute dbms_system.set_ev(sid,serial#,10046,12,'');
關閉：execute dbms_system.set_ev(sid,serial#,10046,0,'');
舉例如下：
A.獲得sid, serial#的信息
sys@ora10g> select sid, serial# from v$session;
B.開啟
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,12,'');
C.關閉
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,0,'');
4）在該會話中運行一條具體的SQL語句，此處使用到的實驗表t中包含1億條數據。該SQL語句的執行情況將被細致的記錄到trace文件中。
sec@ora10g> select count(*) from t;
COUNT(*)
----------
100000000
5）關閉當前會話的跟蹤
sec@ora10g> alter session set events '10046 trace name context off';
Session altered.
2.在udump目錄中找到剛剛生成的trace文件（關于如何快速獲得生成的trace文件的方法有很多種，選擇一個適合自己的就OK），并使用TKPROF對其進行格式化，然后打印一下全部輸出，后面將對每一個輸出項做一下“解剖麻雀”:)
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_21213.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
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 5.60 7.74
********************************************************************************
select count(*)
from
t
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 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
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 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 2
Fetch 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 10.94 10.68 222186 222957 0 3
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 5.60 7.74
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
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 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_21213.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
2 unique SQL statements in trace file.
14392 lines in trace file.
16 elapsed seconds in trace file.
3.對上面的TKPROF格式化輸出內容重點內容“解剖麻雀”正式開始
1）摘錄第一部分，SQL語句的執行情況總覽
select count(*)
from
t
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 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
關于統計表格的標題信息中count、cpu、elapsed、disk、query、current和rows的說明在該trace文件的最前端有一個簡要的說明，這里再分別贅述一下。
count ：查詢在此階段執行的次數；
cpu ：該查詢在此階段的CPU時間量，以毫秒為單位；
elapsed ：花費在此階段上的掛鐘時間，該值比cpu值大的時候，表明存在等待事件；
disk ：執行物理I/O次數；
query ：在意一致性檢索方式獲得塊時，執行邏輯I/O次數；
current ：邏輯I/O次數；
rows ：此階段，被處理或受影響的行數。
關于第一列的贅述：
Parse ：軟編譯和硬編譯次數；
Execute ：在open和execute語句中完成的內容;
Fetch ：select中會有數據顯示，在update語句中不會有數據顯示。
2）摘錄運行環境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
第一行的“0”表示查詢使用的是軟解析（soft parse）。
優化模式是：ALL_ROWS
使用最后一行的用戶ID可以獲得執行時的會話信息。獲得用戶信息可以通過下面的SQL語句完成。
sys@ora10g> select * from all_users where user_id = 51;
USERNAME USER_ID CREATED
------------------------------ ---------- -------------------
SEC 51 2009-10-15 13:04:03
3）摘錄執行計劃信息
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
有趣發現：通過第二行可以得到這個t表的數據量，這里顯示結果是1億。
“解剖”上面出現的幾個重要參數：
cr=222957 -- 一致性讀取
pr=222186 -- 物理讀取
pw=0 -- 物理寫
time=100000562 us -- 占用時間，單位：微妙 百萬分之一秒
4）摘錄等待事件
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 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
通過這段等待事件的描述，可以清楚的得到在執行SQL語句的過程中都出現了哪些引人注目的等待事件。比如上面顯示出的“db file scattered read”和“db file sequential read”信息，如果此類信息在生產環境中大量出現，就需要重點深入分析和研究了。
4.小結
整個“解剖麻雀”的過程到此告一段落，相信您對“10046跟蹤”和TKPROF格式化有了一個整體上的了解，這里只是通過一個示例來展示一下trace跟蹤和TKPROF的強大。更重要的是在生產環境故障診斷過程中的具體問題具體分析。這里不得不提醒一下的是，在生產環境中使用10046 level 12方法對會話進行跟蹤時，要充分考慮到它對系統性能的影響，前期測試是必須的步驟。
-- The End --
1.與之上次使用到的SQL_TRACE功能相比，我們這次將使用更高級的trace命令（10046）來做演示。我們先啟用“高級”的10046事件生成一份待格式化的trace文件
1）連接到普通用戶sec
sys@ora10g> conn sec/sec
Connected.
2）先將timed_statistics參數設置為true，這樣可以使TKPROF工具能提供更多的有意義的信息，方便性能診斷
sec@ora10g> alter session set timed_statistics=true;
Session altered.
3）“高級”之所在，我們這里啟用10046的level 12對當前會話進行跟蹤。
（1）在此，給出10046各level的解釋參考：
level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)
等同于標準的SQL_TRACE=TRUE；
level 4 to enable SQL_TRACE and also capture bind variable values in the trace file
啟用SQL_TRACE，并捕捉跟蹤文件中的綁定變量；
level 8 to enable SQL_TRACE and also capture wait events into the trace file
啟用SQL_TRACE，并捕捉跟蹤文件中的等待事件；
level 12 to enable standard SQL_TRACE and also capture bind variables and wait events
啟用SQL_TRACE，并捕捉跟蹤文件中的綁定變量和等待事件（捕獲信息能力最強）。
（2）對當前會話啟用level 12的跟蹤：
sec@ora10g> alter session set events '10046 trace name context forever, level 12';
Session altered.
（3）【補充】如果想使用這種高級方法對其他的會話進行跟蹤的話，可以使用如下的SQL語句開啟和關閉：
開啟：execute dbms_system.set_ev(sid,serial#,10046,12,'');
關閉：execute dbms_system.set_ev(sid,serial#,10046,0,'');
舉例如下：
A.獲得sid, serial#的信息
sys@ora10g> select sid, serial# from v$session;
B.開啟
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,12,'');
C.關閉
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,0,'');
4）在該會話中運行一條具體的SQL語句，此處使用到的實驗表t中包含1億條數據。該SQL語句的執行情況將被細致的記錄到trace文件中。
sec@ora10g> select count(*) from t;
COUNT(*)
----------
100000000
5）關閉當前會話的跟蹤
sec@ora10g> alter session set events '10046 trace name context off';
Session altered.
2.在udump目錄中找到剛剛生成的trace文件（關于如何快速獲得生成的trace文件的方法有很多種，選擇一個適合自己的就OK），并使用TKPROF對其進行格式化，然后打印一下全部輸出，后面將對每一個輸出項做一下“解剖麻雀”:)
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prf
TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: ora10g_ora_21213.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
********************************************************************************
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 0.00 0 0 0 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 0 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
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 5.60 7.74
********************************************************************************
select count(*)
from
t
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 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
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 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 2
Fetch 2 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 10.94 10.68 222186 222957 0 3
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 5.60 7.74
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
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 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
3 user SQL statements in session.
0 internal SQL statements in session.
3 SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_21213.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
3 user SQL statements in trace file.
0 internal SQL statements in trace file.
3 SQL statements in trace file.
2 unique SQL statements in trace file.
14392 lines in trace file.
16 elapsed seconds in trace file.
3.對上面的TKPROF格式化輸出內容重點內容“解剖麻雀”正式開始
1）摘錄第一部分，SQL語句的執行情況總覽
select count(*)
from
t
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 10.94 10.68 222186 222957 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 10.94 10.68 222186 222957 0 1
關于統計表格的標題信息中count、cpu、elapsed、disk、query、current和rows的說明在該trace文件的最前端有一個簡要的說明，這里再分別贅述一下。
count ：查詢在此階段執行的次數；
cpu ：該查詢在此階段的CPU時間量，以毫秒為單位；
elapsed ：花費在此階段上的掛鐘時間，該值比cpu值大的時候，表明存在等待事件；
disk ：執行物理I/O次數；
query ：在意一致性檢索方式獲得塊時，執行邏輯I/O次數；
current ：邏輯I/O次數；
rows ：此階段，被處理或受影響的行數。
關于第一列的贅述：
Parse ：軟編譯和硬編譯次數；
Execute ：在open和execute語句中完成的內容;
Fetch ：select中會有數據顯示，在update語句中不會有數據顯示。
2）摘錄運行環境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51
第一行的“0”表示查詢使用的是軟解析（soft parse）。
優化模式是：ALL_ROWS
使用最后一行的用戶ID可以獲得執行時的會話信息。獲得用戶信息可以通過下面的SQL語句完成。
sys@ora10g> select * from all_users where user_id = 51;
USERNAME USER_ID CREATED
------------------------------ ---------- -------------------
SEC 51 2009-10-15 13:04:03
3）摘錄執行計劃信息
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)
100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)
有趣發現：通過第二行可以得到這個t表的數據量，這里顯示結果是1億。
“解剖”上面出現的幾個重要參數：
cr=222957 -- 一致性讀取
pr=222186 -- 物理讀取
pw=0 -- 物理寫
time=100000562 us -- 占用時間，單位：微妙 百萬分之一秒
4）摘錄等待事件
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 0.00 0.00
db file scattered read 14249 0.00 1.10
db file sequential read 59 0.00 0.00
通過這段等待事件的描述，可以清楚的得到在執行SQL語句的過程中都出現了哪些引人注目的等待事件。比如上面顯示出的“db file scattered read”和“db file sequential read”信息，如果此類信息在生產環境中大量出現，就需要重點深入分析和研究了。
4.小結
整個“解剖麻雀”的過程到此告一段落，相信您對“10046跟蹤”和TKPROF格式化有了一個整體上的了解，這里只是通過一個示例來展示一下trace跟蹤和TKPROF的強大。更重要的是在生產環境故障診斷過程中的具體問題具體分析。這里不得不提醒一下的是，在生產環境中使用10046 level 12方法對會話進行跟蹤時，要充分考慮到它對系統性能的影響，前期測試是必須的步驟。
-- The End --
新聞名稱：【TKPROF】使用TKPROF格式化TRACE輸出之“解剖麻雀”
URL分享：http://www.yijiale78.com/article26/jdohjg.html
成都網站建設公司_創新互聯，為您提供網站改版、品牌網站制作、用戶體驗、、移動網站建設、網站設計公司
聲明：本網站發布的內容（圖片、視頻和文字）以用戶投稿、用戶轉載內容為主，如果涉及侵權請盡快告知，我們將會在第一時間刪除。文章觀點不代表本網站立場，如需處理請聯系客服。電話：028-86922220；郵箱：631063699@qq.com。內容未經允許不得轉載，或轉載時需注明來源： 創新互聯
- 移動時代的APP設計應注意哪些問題？ 2017-01-24
- 移動APP設計中字體排版有何技巧？ 2016-08-16
- 手機APP設計制作定律（一） 2016-11-04
- 移動APP設計趨勢：神奇的微互動 2015-12-03
- APP設計師必知：用戶體驗十大原則！ 2022-06-30
- 設計實戰!科學養護綠植APP設計如何提升用戶體驗 2022-05-01
- 動效-APP設計的肢體語言 2022-06-30
- 成都網站建設整理收集的關于APP設計過程中應注意的事項 2022-12-01
- 小程序的設計，和App設計一樣嗎？ 2022-08-31
- APP設計之--導航 2022-06-22
- 不要在你的移動應用APP設計中犯這7個錯誤 2016-08-20
- APP設計常見的交互樣式有哪些 2021-05-25