利用tkprof檢視trace檔案

生成trace檔案

透過檢視Oracle中的trace檔案，往往有助於我們去分析資料庫dump原因，執行計劃的內部過程，繫結變數的使用情況，以及產生死鎖的原因等等。我們可以透過如下3種方式手工生產trace檔案
開啟trace跟蹤
會話級 

SQL> alter session set sql_trace=true;
SQL> alter session set events '10046 trace name context forever,level 12';
SQL> exec sys.dbms_system.set_sql_trace_in_session(10 , 39196 , true); 
例項級
SQL> alter system set sql_trace=true; 
關閉trace跟蹤 
會話級 
SQL> alter session set sql_trace=false;
SQL> alter session set events '10046 trace name context off';
SQL> exec sys.dbms_system.set_sql_trace_in_session(10 , 39196 , false); 
例項級
SQL> alter system set sql_trace=false; 
tkprof 
語法
$ 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 

這樣可以減少分析出來的檔案的複雜度，便於檢視。

引數說明
tracefile：你要分析的trace檔案
outputfile：格式化後的檔案
explain=user/password@connectstring
table=schema.tablename

PRINT:只列出輸出檔案的最初N個SQL語句。預設為所有的SQL語句。
AGGREGATE:如果= NO，則不對多個相同的SQL進行彙總。如果為yes則對trace檔案中的相同sql進行合併。
INSERT:SQL 語句的一種，用於將跟蹤檔案的統計資訊儲存到資料庫中。在TKPROF建立指令碼後，在將結果輸入到資料庫中。
SYS:如果設定為yes，則所有sys使用者的操作(也包含使用者sql語句引發的遞迴sql)，這樣可以減少分析出來的檔案的複雜度，便於檢視。
TABLE:在輸出到輸出檔案前，用於存放臨時表的使用者名稱和表名。
EXPLAIN:對每條SQL 語句確定其執行規劃，並將執行規劃寫到輸出檔案中。如果不是有explain，在trace檔案中我們看到的是SQL實際的執行路徑，不會有sql的執行計劃
sort:對trace檔案的sql語句根據需要排序，其中比較有用的一個排序選項是fchela，即按照elapsed time fetching來對分析的結果排序（記住要設定初始化引數timed_statistics=true），生成的檔案將把最消耗時間的sql放在最前面顯示。
Tkprof命令輸出的解釋 
首先解釋輸出檔案中列的含義：
CALL：每次SQL語句的處理都分成三個部分
Parse：這步將SQL語句轉換成執行計劃，包括檢查是否有正確的授權和所需要用到的表、列以及其他引用到的物件是否存在。
Execute：這步是真正的由Oracle來執行語句。對於insert、update、delete操作，這步會修改資料，對於select操作，這步就只是確定選擇的記錄。
Fetch：返回查詢語句中所獲得的記錄，這步只有select語句會被執行。
COUNT:這個語句被parse、execute、fetch的次數。
CPU：這個語句對於所有的parse、execute、fetch所消耗的cpu的時間，以秒為單位。
ELAPSED：這個語句所有消耗在parse、execute、fetch的總的時間。
DISK：從磁碟上的資料檔案中物理讀取的塊的數量。
QUERY：在一致性讀模式下，所有parse、execute、fetch所獲得的buffer的數量。一致性模式的buffer是用於給一個長時間執行的事務提供一個一致性讀的快照，快取實際上在頭部儲存了狀態。
CURRENT：在current模式下所獲得的buffer的數量。一般在current模式下執行insert、update、delete操作都會獲取buffer。在current模式下如果在快取記憶體區發現有新的快取足夠給當前的事務使用，則這些buffer都會被讀入了快取區中。
ROWS: 所有SQL語句返回的記錄數目，但是不包括子查詢中返回的記錄數目。對於select語句，返回記錄是在fetch這步，對於insert、update、delete操作，返回記錄則是在execute這步。
trace檔案中的效能分析 
1、如果分析數與執行數之比為1，說明每次執行這個查詢都要進行sql解析。如果分析數與執行數之比接近0，則意味著查詢執行了很多次軟解析，降低了系統的可伸縮性。
2、如果trace檔案中顯示對所有或者幾乎所有的sql都執行一次，那有可能是因為沒有正確使用繫結變數。
3、如果一個(Fetch Count)/所獲得行數的比值接近1，且行數大於1，則應用程式不執行大批次取數操作，每種語言/API都有能力完成這個功能，即一次取多行。如果沒有利用這個功能進行批次去，將有可能花費多得多的時間在客戶端與伺服器端之間來回往返。這個過多的來回轉換出了產生很擁擠的網路狀況之外，也會比一次呼叫獲得很多行要慢得多，如何指示應用程式進行批次獲取將隨語言/API而定。
4、如果CPU時間與elasped時間有巨大差異，意味著有可能花了大量時間在等待某些事情上。如果花了一個CPU時間來執行，但它卻總共花了10秒的時間，這就意味著90%的執行時間在等待一個資源。例如被一個會話等待，或者大量查詢時的物理IO等待等
5、較長的CPU或經過時間往往是最消耗資源的sql，需要我們關注
6、可以透過磁碟IO所佔邏輯IO的比例，disk/query+current來判斷磁碟IO的情況，太大的話有可能是db_buffer_size過小，當然這也跟SQL的具體特性有關
7、query+current/rows 平均每行所需的block數，太大的話（超過20）SQL語句效率太低，資料過於分散，可以考慮重組物件
trace檔案樣例

TKPROF: Release 10.2.0.1.0 - Production on Sun Apr 22 11:00:58 2012
Copyright (c) 1982, 2005, Oracle.  All rights reserved.
Trace file: orcl_ora_4299.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
********************************************************************************
The following statements encountered a error during parse:
BEGIN :a = 99; END;
Error encountered: ORA-06550
--------------------------------------------------------------------------------
alter session set sql_trace=off
Error encountered: ORA-00922
********************************************************************************
error connecting to database using: system/manager
ORA-01017: invalid username/password; logon denied
EXPLAIN PLAN option disabled.
********************************************************************************
select count(*)
from
 t where id = :a
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      0.03       0.04         99        106          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.04       0.05         99        106          0           1
Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55
Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=106 pr=99 pw=0 time=46182 us)
  50422   INDEX FAST FULL SCAN T_IDX (cr=106 pr=99 pw=0 time=4489223 us)(object id 52998)
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       10      0.00       0.01          0          0          0           0
Execute     12      0.01       0.03          0          0          0           3
Fetch       10      0.07       0.08         99        316          0           5
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       32      0.09       0.13         99        316          0           8
Misses in library cache during parse: 8
Misses in library cache during execute: 8
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       47      0.03       0.05          0          0          0           0
Execute    210      0.05       0.07          0          0          0           0
Fetch      328      0.06       0.04          0        852          0         976
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      585      0.15       0.16          0        852          0         976
Misses in library cache during parse: 22
Misses in library cache during execute: 22
   12  user  SQL statements in session.
  210  internal SQL statements in session.
  222  SQL statements in session.
    0  statements EXPLAINed in this session.
********************************************************************************
Trace file: orcl_ora_4299.trc
Trace file compatibility: 10.01.00
Sort options: fchela
       1  session in tracefile.
      12  user  SQL statements in trace file.
     210  internal SQL statements in trace file.
     222  SQL statements in trace file.
      30  unique SQL statements in trace file.
    2131  lines in trace file.
     130  elapsed seconds in trace file.
先看下面解釋 
The compilation of a SQL statement consists of two phases: the parse phase and the execute phase. When the time comes to parse a SQL statement, Oracle first checks to see if the parsed representation of the statement already exists in the library cache. If not, Oracle will allocate a shared SQL area within the library cache and then parse the SQL statement. 
At execution time, Oracle checks to see if a parsed representation of the SQL statement already exists in the library cache. If not, Oracle will reparse and execute the statement. -- the error will come out from this step. could be various reaconsequentlyns why it was flushed out of lc.

Misses in library cache during parse：發生在解析的硬解析數量，如果是軟解析則Misses in library cache during parse將為0 
Misses in library cache during execute：發生在執行呼叫階段的硬解析數量。如果在執行呼叫時沒有硬解析發生，Misses in library cache during execute這一行將不存在。

執行計劃分為兩部分，第一部分稱為行源操作(Row Source Operation )，是遊標關閉且開啟跟蹤情況下寫到跟蹤檔案中的執行計劃。這意味著如果應用程式不關閉遊標而重用它們的話，不會有新的針對重用遊標的執行計劃寫入到跟蹤檔案中。第二部分，叫做執行計劃 (Execution Plan)，是由指定了explain引數的TKPROF生成的。既然這是隨後生成的，所以和第一部分不一定完全匹配。萬一看到兩者不一致，前者是正確的。兩個執行計劃都透過Rows列提供執行計劃中每個操作返回的行數（不是處理的--要注意）。 對於每個行源操作來說，可能還會提供如下的執行時統計： 
cr是一致性模式下邏輯讀出的資料塊數。
pr是從磁碟物理讀出的資料塊數。
pw是物理寫入磁碟的資料塊數。
time是以微秒錶示的總的消逝時間。要注意根據統計得到的值不總是精確的。實際上，為了減少開銷，可能用了取樣。
cost是操作的評估開銷。這個值只有在Oracle 11g才提供。
size是操作返回的預估資料量(位元組數)。這個值只有在Oracle 11g才提供。 
card是操作返回的預估行數。這個值只有在Oracle 11g才提供。

輸出檔案的結尾給出了所有關於跟蹤檔案的資訊。首先可以看到跟蹤檔名稱、版本號、用於這個分析所使用的引數sort的值。然後，給出了所有會話數量與SQL語句數量。 
Optimizer mode: ALL_ROWS表示最佳化器採用的是all_rows的模式
Parsing user id: 55 表示使用者id為55 
Tips:我們可以透過grep total report1.txt來快速檢視需要我們關注的地方，如上例，如果我們認為需要和0.05相關的sql，我們可以直接開啟report1.txt搜尋0.05這個關鍵字 

Examples of TKPROF Statement
This section provides two brief examples of TKPROF usage. For an complete example of TKPROF output, see "Sample TKPROF Output".
TKPROF Example 1
If you are processing a large trace file using a combination of SORT parameters and the PRINT parameter, then you can produce a TKPROF output file containing only the highest resource-intensive statements. For example, the following statement prints the 10 statements in the trace file that have generated the most physical I/O:
TKPROF ora53269.trc ora53269.prf SORT = (PRSDSK, EXEDSK, FCHDSK) PRINT = 10
TKPROF Example 2
This example runs TKPROF, accepts a trace file named examp12_jane_fg_sqlplus_007.trc, and writes a formatted output file named outputa.prf:
TKPROF examp12_jane_fg_sqlplus_007.trc OUTPUTA.PRF
EXPLAIN=scott/tiger TABLE=scott.temp_plan_table_a INSERT=STOREA.SQL SYS=NO
SORT=(EXECPU,FCHCPU)
This example is likely to be longer than a single line on the screen, and you might need to use continuation characters, depending on the operating system.
Note the other parameters in this example:

• The EXPLAIN value causes TKPROF to connect as the user scott and use the EXPLAIN PLAN statement to generate the execution plan for each traced SQL statement. You can use this to get access paths and row source counts.

Note:If the cursor for a SQL statement is not closed, then TKPROF output does not automatically include the actual execution plan of the SQL statement. In this situation, you can use the EXPLAIN option with TKPROF to generate an execution plan.

• The TABLE value causes TKPROF to use the table temp_plan_table_a in the schema scott as a temporary plan table.
• The INSERT value causes TKPROF to generate a SQL script named STOREA.SQL that stores statistics for all traced SQL statements in the database.
• The SYS parameter with the value of NO causes TKPROF to omit recursive SQL statements from the output file. In this way, you can ignore internal Oracle Database statements such as temporary table operations.
• The SORT value causes TKPROF to sort the SQL statements in order of the sum of the CPU time spent executing and the CPU time spent fetching rows before writing them to the output file. For greatest efficiency, always use SORT parameters.