SQL优化及性能诊断(10046事件/tkprof)

最新推荐文章于 2021-08-06 11:00:01 发布

最新推荐文章于 2021-08-06 11:00:01 发布 · 86 阅读

文章标签：

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. WaitTotal 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
----------------------------------------------------------
1SORT 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. WaitTotal 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 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. WaitTotal 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

3userSQL statements in session.
0internal SQL statements in session.
3SQL statements in session.
********************************************************************************
Trace file: ora10g_ora_21213.trc
Trace file compatibility: 10.01.00
Sort options: default

1session in tracefile.
3userSQL statements in trace file.
0internal SQL statements in trace file.
3SQL statements in trace file.
2unique SQL statements in trace file.
14392lines in trace file.
16elapsed 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
----------------------------------------------------------
1SORT 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. WaitTotal 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 --

供您参考。