Finding Trace Files v$diag_info & TKPROF

Finding Trace Files

Trace files are produced by database engine server processes running on the database server. This means they ’re written to a disk accessible from the database server. In version 10.2, depending on the type of the process producing the trace files, they’re written in two distinct directories:

Dedicated server processes create trace files in the directory configured through the

user_dump_dest initialization parameter.Background processes create trace files in the directory configured through the background_dump_dest initialization parameter.

11g 后 user_dump_dest and background_dump_dest 沒用了，使用 diagnostic_dest

As of version 11.1, with the introduction of the Automatic Diagnostic Repository, the user_dump_dest and background_dump_dest initialization parameters are deprecated in favor of the diagnostic_dest initialization parameter. Because the new initialization parameter sets the base directory only, you can use the v$diag_info view to get the exact location of the trace files. The following queries show the difference between the value of the initialization parameter and the location of the trace files:

SQL> SELECT value FROM v$parameter WHERE name = 'diagnostic_dest';

VALUE

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

/u00/app/oracle

SQL> SELECT value FROM v$diag_info WHERE name = 'Diag Trace';

VALUE

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

/u00/app/oracle/diag/rdbms/dbm11203/DBM11203/trace

Note that the v$diag_info view provides information for the current session only.

As of version 11.1, it’s much easier to query either the v$diag_info or v$process views, as shown in the following examples:

SQL> SELECT value FROM v$diag_info WHERE name = 'Default Trace File';

SELECT p.tracefile FROM v$process p, v$session s WHERE p.addr = s.paddr  AND s.sid = sys_context('userenv','sid')

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.