10046之诊断绑定变量问题

最新推荐文章于 2024-09-18 20:58:46 发布

转载最新推荐文章于 2024-09-18 20:58:46 发布 · 191 阅读

本文通过对比两种插入方式的10046追踪文件，分析了使用绑定变量对于减少硬解析次数的重要性，并提供了具体的测试案例及tkprof处理结果。

今天整的是如何用10046来判断绑定变量的问题。（剑破冰山学习笔记）

10046和10053，是两个比较常用的：
10046出来的，是整个sql的执行过程，详细到整个执行过程中每一步的用时，比如：在10046中，可以看到，在解析这一步花了多长时间，在execute多久，fetch多久等等；
10053呢，是针对优化器的，从10053中看到的，是为什么选择一个执行计划。

所做测试如下：
1，创建测试表
SQL> create table test (sno varchar2(32));

Table created.
2.对session开启10046

SQL> alter session set events '10046 trace name context forever,level 12';

Session altered.
不同级别的10046如下：
1 标准的sql_trace
4 level1+bind values
8 level1+等待时间跟踪
12 1+4+8
我用的是12.
同时，level越高，产生的东西越冬tkprof的时间越长，同时对全局session的10046很消耗资源。

3，对test用户开启跟踪
首先，查出test用户的sid，serial。
SQL> select serial#,sid,username from v$session ;

SERIAL# SID USERNAME
---------- ---------- ------------------------------
5 1 SYS
3 41 TEST

下面针对test用户开启跟踪，下面命令sys用户执行
SQL> exec dbms_system.set_ev(41,3,10046,12,'TEST');

PL/SQL procedure successfully completed.

4，执行测试语句

我的语句如下：
SQL> begin
2 for i in 1 .. 100000 loop
3 execute immediate 'insert into test values ('||i||')';
4 end loop;
5 end;
6 /
PL/SQL procedure successfully completed.

5，对test关闭跟踪
SQL> exec dbms_system.set_ev(41,3,10046,0,'TEST');

PL/SQL procedure successfully completed.
6，获取跟踪文件
如下：为跟踪文件的位置，ll -t 可以按照时间倒序查看
SQL> show parameter user_dump_dest
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
user_dump_dest string /u01/diag/rdbms/ora/ora/trace

同时，为了更方便的找到追踪文件，可以执行如下命令：（我没执行）
SQL> alter session set tracefile_identifier='10046';

Session altered.

7，格式化trace文件
tkprof tracefile outfile ［option］
参数如下：

explain=user/password 执行explain命令将结果放在SQL trace的输出文件中

table=schema.table 指定tkprof处理sql trace文件时临时表的模式名和表名
insert=scriptfile 创建一个文件名为scriptfile的文件，包含了tkprof存放的输出sql语句
sys=[yes/no] 确定系统是否列出由sys用户产生或重调的sql语句
print=number 将仅生成排序后的第一条sql语句的输出结果
record=recordfile 这个选项创建一个名为recorderfile的文件，包含了所有重调用的sql语句
sort=sort_option 按照指定的方法对sql trace的输出文件进行降序排序
sort_option 选项
prscnt 按解析次数排序
prscpu 按解析所花cpu时间排序
prsela 按解析所经历的时间排序
prsdsk 按解析时物理的读操作的次数排序
prsqry 按解析时以一致模式读取数据块的次数排序
prscu 按解析时以当前读取数据块的次数进行排序
execnt 按执行次数排序
execpu 按执行时花的cpu时间排序
exeela 按执行所经历的时间排序
exedsk 按执行时物理读操作的次数排序
exeqry 按执行时以一致模式读取数据块的次数排序
execu 按执行时以当前模式读取数据块的次数排序
exerow 按执行时处理的记录的次数进行排序
exemis 按执行时库缓冲区的错误排序
fchcnt 按返回数据的次数进行排序
fchcpu 按返回数据cpu所花时间排序
fchela 按返回数据所经历的时间排序
fchdsk 按返回数据时的物理读操作的次数排序
fchqry 按返回数据时一致模式读取数据块的次数排序
fchcu 按返回数据时当前模式读取数据块的次数排序
fchrow 按返回数据时处理的数据数量排序

我的命令如下：
tkprof ora_ora_2689.trc ora_ora_2689.prf sys=no

8,查看格式化之后的trace文件

tail －n 50 ＋filename 可以查看文件最后50行纪录
手动删掉了一些暂时不关注的内容，要关注的如下：
[oracle@lzw trace]$ tail -n 50 ora_ora_2689.prf

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 100018 20.50 20.35 0 0 10 0
Execute 100115 2.29 2.38 4 100607 303539 100005
Fetch 154 0.00 0.05 5 383 0 464
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 200287 22.80 22.78 9 100990 303549 100469

Misses in library cache during parse: 100018
Misses in library cache during execute: 19

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 9 0.05 0.06

100003 user SQL statements in session.
31 internal SQL statements in session.
100034 SQL statements in session.
********************************************************************************
Trace file: ora_ora_2689.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
100003 user SQL statements in trace file.
31 internal SQL statements in trace file.
100034 SQL statements in trace file.
100026 unique SQL statements in trace file.
802347 lines in trace file.
212 elapsed seconds in trace file.
可以发现，跟踪时间段，22.35+2.38+0.05的时间中，有22.35的时间花在解析上。
同时查看trace前面的内容发现，语句如下：
insert into test values ('1');
insert into test values ('2');
insert into test values ('3');
insert into test values ('4');
insert into test values ('5');
insert into test values ('6');
.
.
.
得出结论，没有使用绑定变量，导致硬解析太高。

下一步，改造sql，以使用绑定变量的方式编码，代码如下：

SQL> truncate table test;
Table truncated.

SQL> begin
2 for i in 1 .. 100000 loop
3 execute immediate 'insert into test values (:v)' using i;
4 end loop;
5 end;
6 /

其余步骤同上：
新生成的10046trace内容如下：

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 100003 2.76 2.83 2 1092 103575 100002
Fetch 1 0.00 0.00 0 4 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 100006 2.76 2.83 2 1096 103575 100003

Misses in library cache during parse: 1
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.00 0.00

2 user SQL statements in session.
3 internal SQL statements in session.
5 SQL statements in session.
********************************************************************************
Trace file: ora_ora_4704_10046.trc
Trace file compatibility: 11.1.0.7
Sort options: default

1 session in tracefile.
2 user SQL statements in trace file.
3 internal SQL statements in trace file.
5 SQL statements in trace file.
5 unique SQL statements in trace file.
800315 lines in trace file.
120 elapsed seconds in trace file.

至此，感谢剑破冰山各位大拿。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/30123160/viewspace-2051322/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/30123160/viewspace-2051322/