使用 Tkprof 分析 ORACLE 跟蹤檔案

路途中的人2012發表於2017-05-06

Tkprof是一個用於分析Oracle跟蹤檔案並且產生一個更加清晰合理的輸出結果的可執行工具。如果一個系統的執行效率比較低,一個比較好的方法是透過跟蹤使用者的會話並且使用Tkprof工具使用排序功能格式化輸出,從而找出有問題的SQL語句。


TKPROF 命令語法:
TKPROF  filename1, filename2 [ SORT  = [ opion][,option] ]
  [  PRINT = integer ]
  [ AGGREGATE  = [ YES | NO ] ]
  [ INSERT = filename3 ]
  [ SYS = [ YES | NO ]  ]
  [  [ TABLE = schema.table ] | [ EXPLAIN = user/password ]  ]
  [  RECORD = filename ]

相關說明:
filename1  指定的輸入檔案,可以是多個檔案聯起來。
Filename2  格式化輸出檔案。
SORT     在輸出到輸出檔案前,先程式排序。如果省去,則按照實際使用的順序輸出到檔案中。排序選項有以下多種:
  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


PRINT        只列出輸出檔案的第一個integer SQL語句。預設為所有的SQL語句。
AGGREGATE    如果= NO ,則不對多個相同的SQL進行彙總。
INSERT       SQL 語句的一種,用於將跟蹤檔案的統計資訊儲存到資料庫中。在TKPROF建立指令碼後,在將結果輸入到資料庫中。
SYS         禁止或啟用 將SYS使用者所釋出的SQL語句列表到輸出檔案中。
TABLE       在輸出到輸出檔案前,用於存放臨時表的使用者名稱和表名。
EXPLAIN     對每條SQL 語句確定其執行規劃。並將執行規劃寫到輸出檔案中。

其中比較有用的一個排序選項是fchela,即按照elapsed time fetching來對分析的結果排序(記住要設定初始化引數timed_statistics=true),生成的檔案將把最消耗時間的sql放在最前面顯示。另外一個有用的引數就是sys,這個引數設定為no可以阻止所有以sys使用者執行的sql被顯示出來,這樣可以減少分析出來的檔案的複雜度,便於檢視。


Tkprof命令輸出的解釋:


首先解釋輸出檔案中列的含義:
CALL:每次SQL語句的處理都分成三個部分
Parse:這步將SQL語句轉換成執行計劃,包括檢查是否有正確的授權和所需要用到的表、列以及其他引用到的物件是否存在。
Execute這步是真正的由Oracle來執行語句。對於insertupdatedelete操作,這步會修改資料,對於select操作,這步就只是確定選擇的記錄。
Fetch返回查詢語句中所獲得的記錄,這步只有select語句會被執行。
COUNT:這個語句被parseexecutefetch的次數。
CPU這個語句對於所有的parseexecutefetch所消耗的cpu的時間,以秒為單位。
ELAPSED這個語句所有消耗在parseexecutefetch總的時間。
DISK從磁碟上的資料檔案中物理讀取的塊的數量。一般來說更想知道的是正在從快取中讀取的資料而不是從磁碟上讀取的資料。
QUERY在一致性讀模式下,所有parseexecutefetch所獲得的buffer的數量。一致性模式的buffer是用於給一個長時間執行的事務提供一個一致性讀的快照,快取實際上在頭部儲存了狀態。
CURRENTcurrent模式下所獲得的buffer的數量。一般在current模式下執行insertupdatedelete操作都會獲取buffer。在current模式下如果在快取記憶體區發現有新的快取足夠給當前的事務使用,則這些buffer都會被讀入了快取區中。
ROWS: 所有SQL語句返回的記錄數目,但是不包括子查詢中返回的記錄數目。對於select語句,返回記錄是在fetch這步,對於insertupdatedelete操作,返回記錄則是在execute這步。


Tkprof的使用步驟基本上遵循以下幾步:
1、設定TIMED_STATISTICSTrue,可以在會話級別,也可以在例項級別。
會話級:
SQL> alter session set timed_statistics=True;
例項級:
SQL> alter system set timed_statistics=True scope=both;
2、 設定SQL_TRACE,可以在會話級,也可以在資料庫級。
會話級:
SQL> alter session set sql_trace=true
或者:
SQL>EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(SID,SERIAL#,TRUE);
例項級:
SQL> alter system set sql_trace=true scope=both;


四.舉例說明:

--啟用SQL_TRACE
SQL> alter session set sql_trace=true;
會話已更改。
SQL> select count(*) from bigtab;

  COUNT(*)

----------

   1922423

--啟用timed_statistics
SQL> alter session set timed_statistics=true;

會話已更改。

SQL>  select count(*) from bigtab;

  COUNT(*)

----------

   1922423

SQL>  alter session set sql_trace =false;

會話已更改。


--查詢此會話產生的TRACE檔案
SQL> select username,sid,serial# from v$session where username='SYS';

USERNAME                              SID    SERIAL#

------------------------------ ---------- ----------

SYS                                    19       2518

SQL> select 'orcl_ora_'||spid||'.trc' from v$process where addr = (select paddr from v$session where sid=19);

'DSS_ORA_'||SPID||'.TRC'

------------------------------------

orcl_ora_7240.trc

也可以透過下面的函式來獲取當前的trace檔案:

create or replace function gettracename  return varchar2 is
  v_result varchar2(200);
begin
  SELECT    d.VALUE
      || '/'
      || LOWER (RTRIM (i.INSTANCE, CHR (0)))
      || '_ora_'
      || p.spid
      || '.trc' into v_result
  FROM (SELECT p.spid
          FROM v$mystat m, v$session s, v$process p
        WHERE m.statistic# = 1 AND s.SID = m.SID AND p.addr = s.paddr) p,
      (SELECT t.INSTANCE
          FROM v$thread t, v$parameter v
        WHERE v.NAME = 'thread'
          AND (v.VALUE = 0 OR t.thread# = TO_NUMBER (v.VALUE))) i,
      (SELECT VALUE
          FROM v$parameter
        WHERE NAME = 'user_dump_dest') d; 
  return v_result;
end gettracename;

執行SQL> select gettracename() from dual;即可
SQL> select gettracename() from dual;

GETTRACENAME()

--------------------------------------------------------------------------

d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc


--使用tkprof分析trace檔案
C:/Users/Administrator.DavidDai>tkprof d:/app/administrator/diag/rdbms/orcl/orcl

/trace/orcl_ora_7240.trc D:/orcl_ora_7240.txt aggregate=yes sys=no waits=yes sor

t=fchela

TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.


--tkprocf輸出了以下檔案:D:/orcl_ora_7240.txt 

TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc

Sort options: fchela  

********************************************************************************

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

********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        4      0.00       0.00          0          0          0           0

Execute      5      0.00       0.00          0          0          0           0

Fetch        4      0.79       7.45      57075      57082          0           2

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total       13      0.79       7.45      57075      57082          0           2

Misses in library cache during parse: 3

Misses in library cache during execute: 1

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

    5  user  SQL statements in session.

    0  internal SQL statements in session.

    5  SQL statements in session.

********************************************************************************

Trace file: d:/app/administrator/diag/rdbms/orcl/orcl/trace/orcl_ora_7240.trc

Trace file compatibility: 11.1.0.7

Sort options: fchela  

       1  session in tracefile.

       5  user  SQL statements in trace file.

       0  internal SQL statements in trace file.

       5  SQL statements in trace file.

       5  unique SQL statements in trace file.

      73  lines in trace file.

      75  elapsed seconds in trace file.


.  分析會話的示例
先從os上利用top命令找到當前佔用cpu資源最高的一個程式的PID號:14483
然後在資料庫中根據PID號找到相應的sid號和serial#
SQL> select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and p.spid='14483';
       SID    SERIAL#
---------- ----------
       101      25695


使用dbms_system.set_sql_trace_in_session包來對這個session進行trace
SQL> exec DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(101,25695,true);
PL/SQL procedure successfully completed.


user_dump_dest定義的路徑下查詢剛剛最近生成的trace檔案,可以根據時間來排序,找最近的trace檔案,也可以根據SID_ORA_SPID.TRC的規則,即ORCL_ORA_14483.TRC找到TRACE檔案。

接著使用tkprof工具對此trace檔案進行格式化分析,生成分析後的trace檔案。
$tkprof orcl_ora_14483.trc allan.txt explain=system/manager aggregate=yes sys=no waits=yes sort=fchela


TKPROF: Release 11.2.0.1.0 - Development on 星期五 5月 28 16:48:49 2010

Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.


這裡生成的allan.txt檔案就是我們最終得到的格式化後的trace檔案了,然後開啟這個檔案進行分析。
最後總的統計:
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call    count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------   --------
Parse     20      0.01       0.02          0         58         0           0
Execute 13197     0.81       0.90         17       7436     6316          1484
Fetch   12944    22.86      22.10         20    2205941        0          8972
------- ------  -------- ---------- ---------- ---------- ---------- --------
total    26161     23.68     23.02         37    2213435     6316       10456

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/29067253/viewspace-2138589/,如需轉載,請註明出處,否則將追究法律責任。

相關文章