tkprof工具詳解二（一些執行個體）

TKPROF是一個可執行檔案，自帶在Oracle Server軟體中，無需額外的安裝。 該工具檔案可以用來解析ORACLE的SQL TRACE(10046) 以便生成更可讀的内容。  實際上tkprof是對10046 SQL trace的内容作了彙總，例如一個語句遇到過的wait event 、其在PARSE、Execute、Fetch三階段的耗時、CPU_TIME等等。

由于tkprof是對10046 SQL TRACE的彙總，是以tkprof中的資訊 完全可以從10046中獲得， 10046的問題是 由于巨細靡遺 是以TRACE内容可能過多，内容多則難以快速分析， TKPROF将10046  trace 解析過後更适合調優者閱讀。

基本步驟：

1、設定TIMED_STATISTICS為True，可以在會話級别，也可以在執行個體級别。

會話級：

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_trace跟蹤檔案

SQL> alter session set sql_trace=true;

Session altered.

SQL> select count(*) from t;

  COUNT(*)

----------

    250734

SQL> alter session set timed_statistics=true;

SQL> alter session set sql_trace =false;

檢視生成的trace檔案

SQL> SELECT d.VALUE || '/' || LOWER(RTRIM(i.INSTANCE, CHR(0))) || '_ora_' ||

           p.spid || '.trc' trace_file_name

  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

       /

TRACE_FILE_NAME

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

/u01/app/oracle/diag/rdbms/db11/db112/trace/db112_ora_7677.trc

使用tkprof分析trace檔案

db112@dbrac2  /home/oracle$ tkprof   /u01/app/oracle/diag/rdbms/db11/db112/trace/db112_ora_7677.trc   db112_ora_7677.txt   aggregate=yes   sys=no   waits=yes   sort=fchela

檢視輸出的檔案

db112@dbrac2  /home/oracle$ cat db112_ora_7677.txt

TKPROF: Release 11.2.0.1.0 - Development on Wed Feb 19 22:13:19 2014

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

Trace file: /u01/app/oracle/diag/rdbms/db11/db112/trace/db112_ora_7677.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

SQL ID: cyzznbykb509s

Plan Hash: 2966233522

select count(*)

from

t

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           0

Fetch        4      0.09       1.51       7294       7298          0           2

total        8      0.09       1.52       7294       7298          0           2

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 127 

Rows     Row Source Operation

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

      1  SORT AGGREGATE (cr=3649 pr=3647 pw=0 time=0 us)

250734   TABLE ACCESS FULL T (cr=3649 pr=3647 pw=0 time=67962 us cost=994 size=0 card=250734)

SQL ID: 4tk6t8tfsfqbf

Plan Hash: 0

alter session set sql_trace=true

Parse        0      0.00       0.00          0          0          0           0

Execute      1      0.00       0.04          7         56          0           0

Fetch        0      0.00       0.00          0          0          0           0

total        1      0.00       0.04          7         56          0           0

Misses in library cache during parse: 0

Misses in library cache during execute: 1

SQL ID: dqcjr8t9drmkw

alter session set sql_trace =false

Parse        1      0.00       0.00          0          0          0           0

Execute      1      0.00       0.00          0          0          0           0

total        2      0.00       0.00          0          0          0           0

SQL ID: cf0ac3jj8sa1c

alter session set timed_statistics=true

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

Parse        4      0.00       0.00          0          0          0           0

Execute      5      0.00       0.04          7         56          0           0

total       13      0.10       1.57       7301       7354          0           2

Misses in library cache during parse: 2

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

Parse       11      0.01       0.02          0          0          0           0

Execute    227      0.07       0.13          0          0          0           0

Fetch      242      0.01       0.25         39        728          0        2129

total      480      0.10       0.41         39        728          0        2129

Misses in library cache during parse: 10

Misses in library cache during execute: 10

    5  user  SQL statements in session.

  227  internal SQL statements in session.

  232  SQL statements in session.

Trace file compatibility: 11.1.0.7

       2  sessions in tracefile.

       5  user  SQL statements in trace file.

     227  internal SQL statements in trace file.

     232  SQL statements in trace file.

      15  unique SQL statements in trace file.

    1760  lines in trace file.

      34  elapsed seconds in trace file.

下面這個例子來自于Maclean

先從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分析檔案

tkprof db112_mmnl_20698.trc ~/20698.txt explain=system/oracle aggregate=yes sys=no waits=yes sort=fchela

對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這步。

筆記