跟踪 SESSION 与 trace 文件解析

我这里是通过学习 Eygle 的 BLOG 中使用 DBMS_SUPPORT 包跟踪 SESSION 来生成跟踪文件， 然后分析问题。怎么用利用 DBMS_SUPPORT 跟踪 session ，这里有 Eygle 的连接很详细了。 http://www.eygle.com/archives/2004/06/dbms_support.html

我们这里主要学习一下分析生成的跟踪文件。

[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 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 )

http://www.eygle.com/archives/2004/06/dbms_support.html （eygle）

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

ITPub博客

跟踪SESSION 与 trace 文件解析

最新文章