跟蹤SESSION 與 trace 檔案解析

我這裡是透過學習Eygle的BLOG中使用DBMS_SUPPORT包跟蹤SESSION來生成跟蹤檔案，然後分析問題。怎麼用利用DBMS_SUPPORT跟蹤session，這裡有Eygle的連線,很詳細了。

我們這裡主要學習一下分析生成的跟蹤檔案。

[ora@dg-pp udump]$ tkprof research_ora_3418.trc b.txt sys=no

上面這條命令：sys=no 只是為了我們們分析session更方便罷了，把所有sys使用者執行的SQL不顯示出來，如果這個檔案research_ora_3418.trc 不用tkprof 格式化輸出的話，我們是很難分析的。tkprof工具為我們分析trace檔案起到了很大的作用。

TKPROF: Release 10.2.0.1.0 - Production on Mon Apr 2 01:11:52 2012

[ora@dg-pp udump]$ cat b.txt

TKPROF: Release 10.2.0.1.0 - Production on Mon Apr 2 01:11:52 2012

Trace file: research_ora_3418.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

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

The following statement encountered a error during parse:

select tname,tabtype from tab where tabtype='TABLE' rownum<2

Error encountered: ORA-00933 （這裡記錄的是執行的SQL和報錯，我們這裡是執行的語法錯誤，很智慧哦，ORACLE先告訴你什麼錯誤，然後寫出SQL，再描述報錯資訊）

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

select count(*)

from

tab

這裡記錄我們執行的SQL，並記錄了一些消耗資訊。便於我們分析。

call count cpu elapsed disk query current rows

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

Parse 1 0.01 0.00 0 0 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.05 0.01 1 812 0 1

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

total 4 0.06 0.01 1 812 0 1

Misses in library cache during parse: 1 #shared pool 中沒有命令，說明做了1次硬解析，軟解析此處為0

Optimizer mode: ALL_ROWS （最佳化器採用的模式）

Parsing user id: 56

Rows Row Source Operation

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

1 SORT AGGREGATE (cr=812 pr=1 pw=0 time=10130 us)

183 NESTED LOOPS OUTER (cr=812 pr=1 pw=0 time=8125 us)

183 TABLE ACCESS FULL OBJ$ (cr=610 pr=0 pw=0 time=6574 us)

13 TABLE ACCESS CLUSTER TAB$ (cr=202 pr=1 pw=0 time=3512 us)

16 INDEX UNIQUE SCAN I_OBJ# (cr=185 pr=1 pw=0 time=1819 us)(object id 3)

cr是一致性模式下邏輯讀出的資料塊數。
pr是從磁碟物理讀出的資料塊數。
pw是物理寫入磁碟的資料塊數。
time是以微秒錶示的總的消逝時間。要注意根據統計得到的值不總是精確的。實際上，為了減少開銷，可能用了取樣。
cost是操作的評估開銷。這個值只有在Oracle 11g才提供。
size是操作返回的預估資料量(位元組數)。這個值只有在Oracle 11g才提供。
card是操作返回的預估行數。這個值只有在Oracle 11g才提供。

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

db file sequential read 1 0.00 0.00

SQL*Net message from client 3 0.00 0.00

SQL*Net break/reset to client 2 0.00 0.00

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

select tname,tabtype

from

tab where tabtype='TABLE' and rownum<2

call count cpu elapsed disk query current rows

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

Parse 1 0.01 0.00 0 2 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.00 0.00 0 611 0 1

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

total 4 0.01 0.00 0 613 0 1

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 56

Rows Row Source Operation

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

1 COUNT STOPKEY (cr=611 pr=0 pw=0 time=580 us)

1 NESTED LOOPS OUTER (cr=611 pr=0 pw=0 time=564 us)

1 TABLE ACCESS FULL OBJ$ (cr=608 pr=0 pw=0 time=511 us)

1 TABLE ACCESS CLUSTER TAB$ (cr=3 pr=0 pw=0 time=32 us)

1 INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=13 us)(object id 3)

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 0.00 0.00

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

select count(*)

from

HB_EMAIL_TEST20120405

call count cpu elapsed disk query current rows

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

Parse 1 0.01 0.00 0 0 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 2 0.79 0.20 3840 7591 1 1

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

total 4 0.80 0.20 3840 7591 1 1

Misses in library cache during parse: 1

Optimizer mode: ALL_ROWS

Parsing user id: 56

Rows Row Source Operation

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

1 SORT AGGREGATE (cr=7591 pr=3840 pw=0 time=201751 us)

597354 TABLE ACCESS FULL HB_EMAIL_TEST20120405 (cr=7591 pr=3840 pw=0 time=4816013 us)

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

db file sequential read 3 0.00 0.00

db file parallel read 1 0.03 0.03

db file scattered read 480 0.00 0.05

SQL*Net message from client 2 0.00 0.00

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

（統計全部不遞迴宣告，這個可以綜合等待事件和解析語法來觀察。）

call count cpu elapsed disk query current rows

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

Parse 3 0.04 0.00 0 2 0 0

Execute 3 0.00 0.00 0 0 0 0

Fetch 6 0.84 0.21 3841 9014 1 3

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

total 12 0.88 0.22 3841 9016 1 3

Misses in library cache during parse: 3

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

db file sequential read 4 0.00 0.00

SQL*Net message to client 13 0.00 0.00

SQL*Net message from client 13 7.07 21.11

SQL*Net break/reset to client 2 0.00 0.00

db file parallel read 1 0.03 0.03

db file scattered read 480 0.00 0.05

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

（統計全部遞迴宣告，這個可以綜合等待事件和解析語法來觀察。）

call count cpu elapsed disk query current rows

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

Parse 36 0.04 0.00 0 0 0 0

Execute 206 0.21 0.04 0 0 0 0

Fetch 226 0.11 0.01 43 615 0 428

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

total 468 0.37 0.07 43 615 0 428

Misses in library cache during parse: 25

Misses in library cache during execute: 25

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

db file sequential read 43 0.00 0.00

3 user SQL statements in session.

206 internal SQL statements in session.

209 SQL statements in session.

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

Trace file: research_ora_3418.trc

Trace file compatibility: 10.01.00

Sort options: default

1 session in tracefile.

一個會話

3 user SQL statements in trace file.

使用者3條SQL

206 internal SQL statements in trace file.

內部206條 SQL

209 SQL statements in trace file.

209條 SQL語句

28 unique SQL statements in trace file.

28唯一SQL

2368 lines in trace file.

14 elapsed seconds in trace file.

總事件14秒

輸出檔案的結尾給出了所有關於跟蹤檔案的資訊。首先可以看到跟蹤檔名稱、版本號、用於這個分析所使用的引數sort的值。然後，給出了所有會話數量與SQL語句數量。

總結：使用包dbms_support跟蹤session (也可以用來跟蹤SQL):

1、可以記錄session執行每一條SQL 3個動作（語法分析，執行，取出）消耗的CPU時間，總時間，物理讀，一致性讀快取區統計，current，所有執行和取出程式數。

2、沒有軟解析的次數，最佳化器選擇模式，使用者ID。

3、Row來源和消耗：邏輯讀出的資料塊數，物理讀出的資料塊數，寫入的資料庫塊數。

4、等待事件，遞迴或不遞迴查詢，最後統計會話的SQL語句多少條，內部執行多少條（這裡讓我對一個SQL執行有了更深的瞭解，一條SQL執行，要先進行這麼多內部SQL，真的很神奇）

感謝以下3位老師

本文參考：http://czmmiao.iteye.com/blog/1493765 (czmmiao)

（eygle）

http://blog.csdn.net/tianlesoftware/article/details/5857023 (tianlesoftware)

跟蹤session 與 trace檔案分析

相關文章