溫馨提示×

溫馨提示×

您好，登錄后才能下訂單哦！

密碼登錄×
登錄注冊×
其他方式登錄
點擊 登錄注冊 即表示同意《億速云用戶服務(wù)條款》

【TKPROF】使用TKPROF格式化TRACE輸出之“解剖麻雀”

發(fā)布時間：2020-08-16 15:15:43 來源：ITPUB博客 閱讀：149 作者：Davis_itpub 欄目：建站服務(wù)器
《【SQL_TRACE】SQL優(yōu)化及性能診斷好幫手》http://space.itpub.net/519536/viewspace-616240中簡單的提到了使用TKPROF工具格式化SQL_TRACE的輸出信息的方法，并沒有對輸出的內(nèi)容做比較清楚的描述，通過這個小文兒，展示一下TKPROF對trace文件格式化的魅力，這里只給出具體輸出信息含義的描述，不展示真實的性能診斷案例。

1.與之上次使用到的SQL_TRACE功能相比，我們這次將使用更高級的trace命令（10046）來做演示。我們先啟用“高級”的10046事件生成一份待格式化的trace文件
1）連接到普通用戶sec
sys@ora10g> conn sec/sec
Connected.

2）先將timed_statistics參數(shù)設(shè)置為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語句開啟和關(guān)閉：
開啟：execute dbms_system.set_ev(sid,serial#,10046,12,'');
關(guān)閉：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.關(guān)閉
sys@ora10g> execute dbms_system.set_ev(543,1306,10046,0,'');

4）在該會話中運行一條具體的SQL語句，此處使用到的實驗表t中包含1億條數(shù)據(jù)。該SQL語句的執(zhí)行情況將被細致的記錄到trace文件中。
sec@ora10g> select count(*) from t;

  COUNT(*)
----------
 100000000

5）關(guān)閉當前會話的跟蹤
sec@ora10g> alter session set events '10046 trace name context off';

Session altered.

2.在udump目錄中找到剛剛生成的trace文件（關(guān)于如何快速獲得生成的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格式化輸出內(nèi)容重點內(nèi)容“解剖麻雀”正式開始
1）摘錄第一部分，SQL語句的執(zhí)行情況總覽
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

關(guān)于統(tǒng)計表格的標題信息中count、cpu、elapsed、disk、query、current和rows的說明在該trace文件的最前端有一個簡要的說明，這里再分別贅述一下。
count   ：查詢在此階段執(zhí)行的次數(shù)；
cpu     ：該查詢在此階段的CPU時間量，以毫秒為單位；
elapsed ：花費在此階段上的掛鐘時間，該值比cpu值大的時候，表明存在等待事件；
disk    ：執(zhí)行物理I/O次數(shù)；
query   ：在意一致性檢索方式獲得塊時，執(zhí)行邏輯I/O次數(shù)；
current ：邏輯I/O次數(shù)；
rows    ：此階段，被處理或受影響的行數(shù)。

關(guān)于第一列的贅述：
Parse   ：軟編譯和硬編譯次數(shù)；
Execute ：在open和execute語句中完成的內(nèi)容;
Fetch   ：select中會有數(shù)據(jù)顯示，在update語句中不會有數(shù)據(jù)顯示。

2）摘錄運行環(huán)境信息
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 51

第一行的“0”表示查詢使用的是軟解析（soft parse）。
優(yōu)化模式是：ALL_ROWS
使用最后一行的用戶ID可以獲得執(zhí)行時的會話信息。獲得用戶信息可以通過下面的SQL語句完成。
sys@ora10g> select * from all_users where user_id = 51;

USERNAME                          USER_ID CREATED
------------------------------ ---------- -------------------
SEC                                    51 2009-10-15 13:04:03

3）摘錄執(zhí)行計劃信息
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)

有趣發(fā)現(xiàn)：通過第二行可以得到這個t表的數(shù)據(jù)量，這里顯示結(jié)果是1億。
“解剖”上面出現(xiàn)的幾個重要參數(shù)：
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

通過這段等待事件的描述，可以清楚的得到在執(zhí)行SQL語句的過程中都出現(xiàn)了哪些引人注目的等待事件。比如上面顯示出的“db file scattered read”和“db file sequential read”信息，如果此類信息在生產(chǎn)環(huán)境中大量出現(xiàn)，就需要重點深入分析和研究了。

4.小結(jié)
整個“解剖麻雀”的過程到此告一段落，相信您對“10046跟蹤”和TKPROF格式化有了一個整體上的了解，這里只是通過一個示例來展示一下trace跟蹤和TKPROF的強大。更重要的是在生產(chǎn)環(huán)境故障診斷過程中的具體問題具體分析。這里不得不提醒一下的是，在生產(chǎn)環(huán)境中使用10046 level 12方法對會話進行跟蹤時，要充分考慮到它對系統(tǒng)性能的影響，前期測試是必須的步驟。

-- The End --
向AI問一下細節(jié)

免責聲明：本站發(fā)布的內(nèi)容（圖片、視頻和文字）以原創(chuàng)、轉(zhuǎn)載和分享為主，文章觀點不代表本網(wǎng)站立場，如果涉及侵權(quán)請聯(lián)系站長郵箱：is@yisu.com進行舉報，并提供相關(guān)證據(jù)，一經(jīng)查實，將立刻刪除涉嫌侵權(quán)內(nèi)容。

AI
助
手