使用TKPROF格式化TRACE输出之"解剖麻雀"

【TKPROF 】使用TKPROF 格式化TRACE 输出之“解剖麻雀” 2009-10-21 11:26:54 《【SQL_TRACE】SQL 优化及性能诊断好帮手》

http://space.itpub.net/519536/viewspace-616240中简单的提到了使用TKPROF 工具格式化SQL_TRACE的输出信息的方法，并没有对输出的内容做比较清楚的描述，通过这个小文儿，展示一下TKPROF 对trace 文件格式化的魅力，这里只给出具体输出信息含义的描述，不展示真实的性能诊断案例。

1. 与之上次使用到的SQL_TRACE功能相比，我们这次将使用更高级的trace 命令（10046）来做演示。我们先启用“高级”的10046事件生成一份待格式化的trace 文件

1）连接到普通用户sec

sys@ora10g> conn sec/sec

Connected.

2）先将timed_statistics参数设置为true ，这样可以使TKPROF 工具能提供更多的有意义的信息，方便性能诊断

sec@ora10g> alter session set timed_statistics=true;

Session altered.

3）“高级”之所在，我们这里启用10046的level 12对当前会话进行跟踪。

（1）在此，给出10046各level 的解释参考：

level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)

等同于标准的SQL_TRACE=TRUE；

level 4 to enable SQL_TRACE and also capture bind variable values in the trace file

启用SQL_TRACE，并捕捉跟踪文件中的绑定变量；

level 8 to enable SQL_TRACE and also capture wait events into the trace file

启用SQL_TRACE，并捕捉跟踪文件中的等待事件；

level 12 to enable standard SQL_TRACE and also capture bind variables and wait events

启用SQL_TRACE，并捕捉跟踪文件中的绑定变量和等待事件（捕获信息能力最强）。

（2）对当前会话启用level 12的跟踪：

sec@ora10g> alter session set events '10046 trace name context forever, level 12';

Session altered.

（3）【补充】如果想使用这种高级方法对其他的会话进行跟踪的话，可以使用如下的SQL 语句开启和关闭：

开启：execute dbms_system.set_ev(sid,serial#,10046,12,''); 关闭：execute dbms_system.set_ev(sid,serial#,10046,0,''); 举例如下：

A. 获得sid, serial#的信息

sys@ora10g> select sid, serial# from v$session;

B. 开启

sys@ora10g> execute

dbms_system.set_ev(543,1306,10046,12,'');

C. 关闭

sys@ora10g> execute

dbms_system.set_ev(543,1306,10046,0,'');

4）在该会话中运行一条具体的SQL 语句，此处使用到的实验表t 中包含1亿条

数据。该SQL 语句的执行情况将被细致的记录到trace 文件中。

sec@ora10g> select count(*) from t;

COUNT(*)

----------

100000000

5）关闭当前会话的跟踪

sec@ora10g> alter session set events '10046 trace name context off';

Session altered.

2. 在udump 目录中找到刚刚生成的trace 文件（关于如何快速获得生成的trace 文件的方法有很多种，选择一个适合自己的就OK ），并使用TKPROF 对其进行格式化，然后打印一下全部输出，后面将对每一个输出项做一下“解剖麻雀”:)

ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ tkprof

ora10g_ora_21213.trc ora10g_ora_21213.prf

TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:04:40 2009

Copyright (c) 1982, 2005, Oracle. All rights reserved.

ora10g@secDB /oracle/app/oracle/admin/ora10g/udump$ cat

ora10g_ora_21213.prf

TKPROF: Release 10.2.0.3.0 - Production on Wed Oct 21 10:05:43 2009

Copyright (c) 1982, 2005, Oracle. All rights reserved.

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

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

BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;

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 2

Fetch 0 0.00 0.00 0 0 0 0

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

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

total 4 0.00 0.00 0 0 0 2

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

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 5.60 7.74

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

select count(*)

from

t

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 10.94 10.68 222186 222957 0 1

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

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

total 4 10.94 10.68 222186 222957 0 1

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

Rows Row Source Operation

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

1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us) 100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)

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

SQL*Net message from

client 3 0.00 0.00

db file scattered

read 14249 0.00 1.10

db file sequential

read 59 0.00 0.00

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows

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

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

Parse 3 0.00 0.00 0 0 0

Execute 3 0.00 0.00 0 0 0 2

Fetch 2 10.94 10.68 222186 222957 0 1

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

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

total 8 10.94 10.68 222186 222957 0 3

Misses in library cache during parse: 0

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

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

SQL*Net message to

client 5 0.00 0.00

SQL*Net message from

client 5 5.60 7.74

db file scattered

read 14249 0.00 1.10

db file sequential

read 59 0.00 0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows

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

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

Parse 0 0.00 0.00 0 0 0 0

Execute 0 0.00 0.00 0 0 0 0

Fetch 0 0.00 0.00 0 0 0 0

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

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

total 0 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0

3 user SQL statements in session.

0 internal SQL statements in session.

3 SQL statements in session.

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

Trace file: ora10g_ora_21213.trc

Trace file compatibility: 10.01.00

Sort options: default

1 session in tracefile.

3 user SQL statements in trace file.

0 internal SQL statements in trace file.

3 SQL statements in trace file.

2 unique SQL statements in trace file.

14392 lines in trace file.

16 elapsed seconds in trace file.

3. 对上面的TKPROF 格式化输出内容重点内容“解剖麻雀”正式开始

1）摘录第一部分，SQL 语句的执行情况总览

select count(*)

from

t

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 10.94 10.68 222186 222957 0 1

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

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

total 4 10.94 10.68 222186 222957 0 1

关于统计表格的标题信息中count 、cpu 、elapsed 、disk 、query 、current 和rows 的说明在该trace 文件的最前端有一个简要的说明，这里再分别赘述一下。

count ：查询在此阶段执行的次数；

cpu ：该查询在此阶段的CPU 时间量，以毫秒为单位；

elapsed ：花费在此阶段上的挂钟时间，该值比cpu 值大的时候，表明存在等待事件；

disk ：执行物理I/O次数；

query ：在意一致性检索方式获得块时，执行逻辑I/O次数；

current ：逻辑I/O次数；

rows ：此阶段，被处理或受影响的行数。

关于第一列的赘述：

Parse ：软编译和硬编译次数；

Execute ：在open 和execute 语句中完成的内容;

Fetch ：select 中会有数据显示，在update 语句中不会有数据显示。

2）摘录运行环境信息

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

第一行的“0”表示查询使用的是软解析（soft parse）。

优化模式是：ALL_ROWS

使用最后一行的用户ID 可以获得执行时的会话信息。获得用户信息可以通过下面的SQL 语句完成。

sys@ora10g> select * from all_users where user_id = 51;

USERNAME USER_ID CREATED

------------------------------ ---------- ------------------- SEC 51 2009-10-15 13:04:03

3）摘录执行计划信息

Rows Row Source Operation

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

1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us) 100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us)(object id 45619)

有趣发现：通过第二行可以得到这个t 表的数据量，这里显示结果是1亿。 “解剖”上面出现的几个重要参数：

cr=222957 -- 一致性读取

pr=222186 -- 物理读取

pw=0 -- 物理写

time=100000562 us -- 占用时间，单位：微妙 百万分之一秒

4）摘录等待事件

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

SQL*Net message from

client 3 0.00 0.00

db file scattered

read 14249 0.00 1.10

db file sequential

read 59 0.00 0.00

通过这段等待事件的描述，可以清楚的得到在执行SQL 语句的过程中都出现了哪些引人注目的等待事件。比如上面显示出的“db file scattered read”和“db file sequential read”信息，如果此类信息在生产环境中大量出现，就需要重点深入分析和研究了。

4. 小结

整个“解剖麻雀”的过程到此告一段落，相信您对“10046跟踪”和TKPROF 格式化有了一个整体上的了解，这里只是通过一个示例来展示一下trace 跟踪和TKPROF 的强大。更重要的是在生产环境故障诊断过程中的具体问题具体分析。

这里不得不提醒一下的是，在生产环境中使用10046 level 12方法对会话进行跟踪时，要充分考虑到它对系统性能的影响，前期测试是必须的步骤。

-- The End --