一次某优化工具厂商的朋友,发来一个案例请求协助诊断,朋友的优化工具在客户的环境中执行某个 SQL 查询时,需要 10 分钟时间才能出结果,这是无法接受的,而同样的查询在其他环境上都可以快速的获得输出结果,数据库环境是 9.2.0.8 。
首先我获得了一个 10046 跟踪文件,通过 tkprof 格式化之后,这个 SQL 的输出结果展现出来。
首先该 SQL 代码如下:
该段 SQL 的 Elapsed 时间超过了 600 秒, Query 模式逻辑读也非常高,对于一个优化工具来说显然是不可接受的。
接下来的跟踪文件中显示了 SQL 的执行计划:
Rows Row Source Operation
------- ---------------------------------------------------
0 NESTED LOOPS OUTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS
0 NESTED LOOPS OUTER
0 NESTED LOOPS
0 NESTED LOOPS OUTER
0 NESTED LOOPS OUTER
0 NESTED LOOPS
0 NESTED LOOPS
0 NESTED LOOPS
1935557 NESTED LOOPS
2863 NESTED LOOPS
2863 NESTED LOOPS
2863 NESTED LOOPS
1 NESTED LOOPS
1 TABLE ACCESS BY INDEX ROWID USER$
1 INDEX UNIQUE SCAN I_USER1 (object id 44)
1 TABLE ACCESS BY INDEX ROWID USER$
1 INDEX UNIQUE SCAN I_USER1 (object id 44)
2863 TABLE ACCESS FULL CDEF$
2863 TABLE ACCESS BY INDEX ROWID CON$
2863 INDEX UNIQUE SCAN I_CON2 (object id 49)
2863 TABLE ACCESS CLUSTER USER$
2863 INDEX UNIQUE SCAN I_USER# (object id 11)
1935557 VIEW
1935557 UNION-ALL PARTITION
1935557 FILTER
1935557 NESTED LOOPS
2863 TABLE ACCESS BY INDEX ROWID USER$
2863 INDEX UNIQUE SCAN I_USER1 (object id 44)
1935557 TABLE ACCESS FULL OBJ$
0 TABLE ACCESS BY INDEX ROWID IND$
0 INDEX UNIQUE SCAN I_IND1 (object id 39)
0 FILTER
0 NESTED LOOPS
0 TABLE ACCESS BY INDEX ROWID USER$
0 INDEX UNIQUE SCAN I_USER1 (object id 44)
0 INDEX RANGE SCAN I_LINK1 (object id 113)
0 TABLE ACCESS BY INDEX ROWID CON$
1935557 INDEX UNIQUE SCAN I_CON2 (object id 49)
0 TABLE ACCESS BY INDEX ROWID CON$
0 INDEX UNIQUE SCAN I_CON1 (object id 48)
0 TABLE ACCESS BY INDEX ROWID CDEF$
0 INDEX UNIQUE SCAN I_CDEF1 (object id 50)
0 TABLE ACCESS BY INDEX ROWID CON$
0 INDEX UNIQUE SCAN I_CON2 (object id 49)
0 TABLE ACCESS CLUSTER USER$
0 INDEX UNIQUE SCAN I_USER# (object id 11)
0 TABLE ACCESS BY INDEX ROWID OBJ$
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 TABLE ACCESS BY INDEX ROWID OBJ$
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 TABLE ACCESS BY INDEX ROWID OBJ$
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 TABLE ACCESS CLUSTER USER$
0 INDEX UNIQUE SCAN I_USER# (object id 11)
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 TABLE ACCESS BY INDEX ROWID OBJ$
0 INDEX UNIQUE SCAN I_OBJ1 (object id 36)
0 TABLE ACCESS CLUSTER USER$
0 INDEX UNIQUE SCAN I_USER# (object id 11)
以上执行计划中,最可疑的部分是对于 OBJ$ 的全表扫描,这个环节的行数返回有 1 , 935 , 557 行,这个量级一直向上传递,所以我们首先怀疑这里的执行计划选择错误,如果选择索引,执行性能肯定会有极大的不同。
可是 10046 的跟踪事件显示的信息比较有限不能够准确定位错误的原因,我请朋友通过 10053 事件来生成一个执行计划的跟踪, 10053 使用极为简便,通过如下方式就可以捕获 SQL 的解析过程:
alter session set events '10053 trace name context forever,level 1';
explain plan for you_select_query;
例如:
SQL> alter session set events '10053 trace name context forever,level 1';
Session altered.
SQL> explain plan for select count(*) from obj$;
Explained.
然后在 udump 目录下就可以找到 10053 生成的跟踪文件,在该文件中,找到了查询相关表的统计信息,其中 OBJ$ 的信息如下所示,其中 CDN ( CarDiNality )指表中包含的记录数量,此处显示 OBJ$ 表中有 24 万左右的记录,使用了 2941 个数据块:
***********************
Table stats Table: OBJ$ Alias: SYS_ALIAS_1
TOTAL :: CDN: 245313 NBLKS: 2941 AVG_ROW_LEN: 79
Column: OWNER# Col#: 3 Table: OBJ$ Alias: SYS_ALIAS_1
NDV: 221 NULLS: 0 DENS: 4.5249e-03 LO: 0 HI: 259
NO HISTOGRAM: #BKT: 1 #VAL: 2
-- Index stats
INDEX NAME: I_OBJ1 COL#: 1
TOTAL :: LVLS: 1 #LB: 632 #DK: 245313 LB/K: 1 DB/K: 1 CLUF: 4184
INDEX NAME: I_OBJ2 COL#: 3 4 5 12 13 6
TOTAL :: LVLS: 2 #LB: 1904 #DK: 245313 LB/K: 1 DB/K: 1 CLUF: 180286
INDEX NAME: I_OBJ3 COL#: 15
TOTAL :: LVLS: 1 #LB: 19 #DK: 2007 LB/K: 1 DB/K: 1 CLUF: 340
_OPTIMIZER_PERCENT_PARALLEL = 0
***************************************
而在前面的 10046 跟踪信息中,显示 OBJ$ 包含大约 200 万条记录,这是非常巨大的不同,对于 USER$ 表,显示具有 2863 条记录,而统计信息中显示仅有 253 条记录:
***********************
Table stats Table: USER$ Alias: U
TOTAL :: CDN: 253 NBLKS: 16 AVG_ROW_LEN: 82
Column: USER# Col#: 1 Table: USER$ Alias: U
NDV: 253 NULLS: 0 DENS: 3.9526e-03 LO: 0 HI: 261
NO HISTOGRAM: #BKT: 1 #VAL: 2
-- Index stats
INDEX NAME: I_USER# COL#: 1
TOTAL :: LVLS: 0 #LB: 1 #DK: 258 LB/K: 1 DB/K: 1 CLUF: 13
INDEX NAME: I_USER1 COL#: 2
TOTAL :: LVLS: 0 #LB: 1 #DK: 253 LB/K: 1 DB/K: 1 CLUF: 87
***********************
这说明数据字典中记录的统计信息与真实情况不符合,导致了 SQL 选择了错误的执行计划,在使用 CBO 的 Oracle9i 数据库中,这种情况极为普遍,通过删除表的统计信息,或者重新收集正确的统计信息,可以使 SQL 执行恢复到正常合理的范畴内。在 Oracle10g 开始的自动统计信息收集,就是为了防止出现统计信息陈旧的现象。
以下是通过 dbms_stats 包清除和重新收集表的统计信息的简单参考:
SQL> exec dbms_stats.delete_table_stats(user,'OBJ$');
PL/SQL procedure successfully completed.
SQL> exec dbms_stats.gather_table_stats(user,'OBJ$');
PL/SQL procedure successfully completed.
基于这样的判断我们建议客户做出修正,最后的客户反馈结果是:按照你的建议,在更新 OBJ$ 的统计信息后,该语句的执行时间由 10 分钟减少到了 2 分钟。接下来,按照类似的思路,又更新了 USER$ , CON$,CDEF$ 表的统计信息,这时,语句的执行时间减少到了零点几秒。至此,问题解决。
参考至:http://www.eygle.com/archives/2011/02/dba_event_10046_10053.html
如有错误,欢迎指正
邮箱:czmcj@163.com