跟蹤 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 跟蹤記錄不轉換過來， research_ora_3418.trc 這個檔案如果不經過 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 跟蹤SESSION 與 trace 檔案解析 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

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

跟蹤SESSION 與 trace 檔案解析 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 檔案解析

相關文章