SQL解析时间过长的调整(案例一则 )

http://www.itpub.net/thread-1845435-1-1.html

某医院生产库迁移到11.2.0.3后，用户抱怨系统变慢。

检查发现，很多复杂SQL的执行很快，但是解析非常慢。
整个数据库并不存在任何争用。
SQL> SELECT SQL_ID,
  AVG_HARD_PARSE_TIME_MS
FROM
(SELECT
    ROUND(AVG_HARD_PARSE_TIME / 1000, 2)
      AVG_HARD_PARSE_TIME_MS,
    SQL_ID,
    EXECUTIONS
  FROM
    V$SQLSTATS
  ORDER BY AVG_HARD_PARSE_TIME DESC )
WHERE
  ROWNUM <= 10;
SQL_ID        AVG_HARD_PARSE_TIME_MS
------------- ----------------------
63n9pwutt8yzw              223279.79
8pduputnkhukx              174644.33
gg9m2b0hjky1y              161064.91
g0vn88sqftx3c               66367.09
bbvy8xjs7gjgj               64747.76
7bgzzkwsqr6hc               63303.48
bzhxncjcy1k96               61963.71
8y387dwxggn5t               57265.29
1f25j21vvfv10               54766.09
0br8s1y3ma0qr               53578.61

以上我们可以看到，某些SQL的解析时间超过百秒。

某一SQL，运行若干次后无物理读：
SQL> /
no rows selected
Elapsed: 00:00:00.11
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
2761 consistent gets
0 physical reads
0 redo size
16589 bytes sent via SQL*Net to client
513 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
3 sorts (memory)
0 sorts (disk)
0 rows processed

在SQL中加入/*hard parse by me*/来硬解析再次执行，同样的逻辑读且无物理读：
no rows selected
Elapsed: 00:00:03.73
Statistics
----------------------------------------------------------
22 recursive calls
0 db block gets
2767 consistent gets
0 physical reads
0 redo size
16589 bytes sent via SQL*Net to client
513 bytes received via SQL*Net from client
1 SQL*Net roundtrips to/from client
3 sorts (memory)
0 sorts (disk)
0 rows processed

以上可见，无硬解析执行0.11秒，因解析执行耗时3.73秒。

这个系统是医院的系统。
应用较复杂，由于应用本身的原因，大量使用拼接SQL, 虽然使用绑定变量，仍然无法避免大量硬解析。

譬如，查询一个病例报告，可以根据：
1.病人ID
2.病人名字
3.病人录入时间
4.手术名称
5.手术时间  
6.主治大夫姓名
7.主治大夫ID
8.疾病种类....
9.疾病严重程度.....
10.病人是否住院
11.身体扫描类型:MRI/XRAY
.......
共三十多个选项，医生可以任意选择其中的N种组合在一起进行查询。
再譬如，对病人名字查询可以使用全匹匹配=,模糊匹配LIKE，大小写不敏感upper等。
对于时间可以选择最近一周内>sysdate-7，或者某一段时间between。
任何一点区别都会造成拼接成的SQL重新硬解析。




首先，通过设置以下参数禁用11g的ACS以减少解析次数。
SQL> show parameter cursor
NAME                                   TYPE       VALUE
-------------------------------------- --------- ----------------------
_optimizer_adaptive_cursor_sharing     boolean   FALSE
_optimizer_extended_cursor_sharing     string    NONE
_optimizer_extended_cursor_sharing_rel string    NONE

在设置以上参数后，情况有初步好转，禁用11g的ACS使得总解析次数减少了80%。

但是，由于每个SQL的解析时间并没有真正减少，用户仍会时不时碰到慢（SQL长时间等待解析）的情况。

下面分析SQL的长解析。首先，数据库不存在任何争用，在午夜零负载的时候，解析耗费时间长的问题仍可重现。
做10046 trace，通过tkprof可以看到：
call    count  cpu      elapsed    disk       query      current    rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse   1      0.01     0.00       0          0          0          0
Execute 1      3.30     3.30       0          6          0          0
Fetch   1      0.00     0.00       0          59         0          0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total   3      3.31     3.31       0          65         0          0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 36
Number of plan statistics captured: 1

以下是10046 raw trace：
PARSING IN CURSOR #18446744071468120416 len=14352 dep=0 uid=36 oct=3 lid=36 tim=40253210782553 hv=3244419326 ad='7a995e8c8' sqlid='d228z5m0q3u7y'
PARSE #18446744071468120416:c=10000,e=9046,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=40253210782549
WAIT #18446744071468120416: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253213924594
WAIT #18446744071468120416: nam='SQL*Net more data to client' ela= 184 driver id=1413697536 #bytes=8145 p3=0 obj#=49430 tim=40253213934106
WAIT #18446744071468120416: nam='SQL*Net message from client' ela= 38091 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253213972419
EXEC #18446744071468120416:c=3310000,e=3313604,p=0,cr=6,cu=0,mis=1,r=0,dep=0,og=1,plh=1738446058,tim=40253217287241
WAIT #18446744071468120416: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253217289638
WAIT #18446744071468120416: nam='SQL*Net more data to client' ela= 181 driver id=1413697536 #bytes=8145 p3=0 obj#=49430 tim=40253217299453
WAIT #18446744071468120416: nam='SQL*Net message from client' ela= 3096 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253217302788
FETCH #18446744071468120416:c=0,e=3601,p=0,cr=59,cu=0,mis=0,r=0,dep=0,og=1,plh=1738446058,tim=40253217306558
WAIT #18446744071468120416: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253217311918
WAIT #18446744071468120416: nam='SQL*Net message from client' ela= 22854 driver id=1413697536 #bytes=1 p3=0 obj#=49430 tim=40253217334883


以上我们可以看到时间并不是耗费在数据字典上，而耗费在了CBO寻径，优化执行计划上。

什么是优化执行计划？为什么时间耗费在Execute上？
我们知道SQL的解析和执行并不是完全隔离的，一个例子就是bind peek：
譬如我们explain plan for select * from t where c1=:n;的时候就可以生成执行计划，但是这个执行计划并是最终的执行计划。
当真正执行时候，传入了变量，oracle会根据变量进行分析，在真正执行时继续调优执行计划，这就是bind peek。


为了排除bind peek的影响，我们用explain plan for来对完全使用绑定变量的SQL进行分析：
explain plan for select /*hard47*/ .......
DECODE(c.c1,:"SYS_B_14",:"SYS_B_15",:"SYS_B_16"),DECODE(c.c2,:"SYS_B_17",:"SYS_B_18",:"SYS_B_19"),
..........
FROM
TABLE1,TABLE2,VIEW1,VIEW2,VIEW3.....
WHERE NVL(QPQD_EX_KEY,:"SYS_B_60") > :"SYS_B_61"  AND   a.QPQD_AP_PATKEY = :1   
Elapsed: 00:00:03.66

在完全使用绑定变量的情况下，同样的SQL解析仍然耗时3秒。


为了使试验更直观，我寻找了一条新的SQL，这条SQL的解析时间是13秒。接下来我会使用这条解析耗费10秒的SQL进行测试。

首先，HINT肯定可以减少缩小CBO的选择范围以减少解析时间，但是对于我们来说不是可选项。

来进行一些基本测试：
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '9.2.0.8'; --- 0.82 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.1.0'; --- 1.03 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.2.0.1'; --- 4.03 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '11.1.0.7'; --- 12.20 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '11.2.0.3'; --- 12.91 seconds
我们可以看到，当OPTIMIZER_FEATURES_ENABLE是当前的11.2.0.3时，解析时间是13秒，当为9.2.0.8，解析时间是0.82秒。

接下来测试optimizer_mode，和预想的一样，在OPTIMIZER_FEATURES_ENABLE仍为11.2.0.3的情况下。当把optimizer_mode设置为RULE后，解析时间变成了0.5秒.

可是，在此生产环境中，我们不能更改OPTIMIZER_FEATURES_ENABLE降级和optimizer_mode=RULE。
首先，这2个参数的误伤/影响范围过广，无法在生产库中轻易尝试。
其次，这2个参数使得解析时间缩短，但使数据库中相关和不相关的其它SQL选择一个错误的执行计划的概率大增。解析时间少了，可执行时间又增加了。
此外，这和提供给用户的升级方案矛盾，毕竟说服用户升级，就是描绘了11g新特性美好的蓝图。

所以，我们希望能够定位问题，然后找到针对此问题的特定参数，能够准确解决问题，同时最小化对系统的影响。


进一步分析问题，为解析耗时13秒的SQL生成了10053 trace。
生成的trace文件是44MB。这是一个好消息。
如果解析用了13秒，但10053 trace只有几百K，说明CBO遇上了严重的BUG，因为几百K的执行计划解析是不应该耗费10多秒的。单trace文件44MB，说明CBO确实有“做事”。

简单的看下10053的内容。我的纯SQL功力只是皮毛，但这不妨碍我们看懂10053 trace的整体框架：
pacsrd1212 $ cat  QPROD_ora_8456_10053.trc|grep -i "permutations tried"|grep -v "permutations tried: 1"
Number of join permutations tried: 2
Number of join permutations tried: 6
Number of join permutations tried: 52
Number of join permutations tried: 2
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 499
Number of join permutations tried: 84
Number of join permutations tried: 2
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 798
Number of join permutations tried: 84
Number of join permutations tried: 80
Number of join permutations tried: 2
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 499
Number of join permutations tried: 84
Number of join permutations tried: 451
Number of join permutations tried: 483
Number of join permutations tried: 84
Number of join permutations tried: 2
Number of join permutations tried: 6
Number of join permutations tried: 52
Number of join permutations tried: 435
Number of join permutations tried: 84

我们对比下OPTIMIZER_FEATURES_ENABLE = '9.2.0.8'时只有2M的10053trace：
pacsrd1212 $ cat QPROD_ora_7830_10053_2.trc|grep -i "permutations tried"|grep -v "permutations tried: 1"
Number of join permutations tried: 2
Number of join permutations tried: 6
Number of join permutations tried: 20
Number of join permutations tried: 2
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 3
Number of join permutations tried: 95

可以看到，OPTIMIZER_FEATURES_ENABLE = '11.2.0.3'时候,CBO考虑了如此多的join order，难怪如此耗时。


我们可以通过隐藏参数“_OPTIMIZER_MAX_PERMUTATIONS”来限定CBO的最大排列组合。
经过测试，在设置_OPTIMIZER_MAX_PERMUTATIONS=50后，SQL解析时间从13秒降低到6秒。

但是此参数同样牵连太广，同时从44MB的10053后，可以看到：
PPOINTMENT_ITEMS[J]#6  QPQD_LINK[QPQD_LINK]#7  VW_NSO_3[VW_NSO_3]#11  QPQD_MACHINELINKS[K]#12  EXAMS[C]#10  EXAMINATIONS[E]#8  EXAMG
ROUPS[F]#9  VW_PRIORITY_SEQUENCE_PLACER[G]#13
Join order aborted: cost > best plan cost
Join order[449]:  QPQDVIEW541[A]#1  PATIENTS[B]#0  QPQD_LINK[Z]#2  APPOINTMENTS[D]#3  APPOINTMENT_ITEMS[H]#4  QPQD_ROOMLINKS[I]#5  A
PPOINTMENT_ITEMS[J]#6  QPQD_LINK[QPQD_LINK]#7  EXAMINATIONS[E]#8  EXAMGROUPS[F]#9  EXAMS[C]#10  VW_NSO_3[VW_NSO_3]#11  QPQD_MACHINEL
INKS[K]#12  VW_PRIORITY_SEQUENCE_PLACER[G]#13
Join order aborted: cost > best plan cost
Considering multiple instances based initial join order.
Best join order so far: 358

CBO在358个join order找到了最优值，所以，如果我们限定_OPTIMIZER_MAX_PERMUTATIONS过小，很可能使得SQL错过此执行计划。


我们来随便看看上面的join order：
QPQDVIEW541[A]#1  PATIENTS[B]#0  QPQD_LINK[Z]#2  APPOINTMENTS[D]#3  APPOINTMENT_ITEMS[H]#4  QPQD_ROOMLINKS[I]#5  A
PPOINTMENT_ITEMS[J]#6  QPQD_LINK[QPQD_LINK]#7  EXAMINATIONS[E]#8  EXAMGROUPS[F]#9  EXAMS[C]#10  VW_NSO_3[VW_NSO_3]#11  QPQD_MACHINEL
INKS[K]#12  VW_PRIORITY_SEQUENCE_PLACER[G]#13
理论上说，14个表，那么对应的可能的执行顺序最多有：14*13*12*11*....*3*2*1种。
当然CBO不会傻到去一一尝试，CBO会在路径判断中忽略大部分必定低效的执行计划。

而其实我们要做的，就是通过各种方式，譬如CBO的parameter，来限制CBO的选择集。CBO无用的选择和尝试越少，那么解析时间就会越少。

至此却陷入困境，不知下一步该怎么继续。
这个时候想起，我们尝试了一个又一个的分析工具，有些时候却忘记了问题本身。

检查了若干解析慢的SQL，发现有某些共通的现象，譬如，解析都包含大量表和复杂视图，已经嵌套若干层的IN/EXIST。
在去掉内层嵌套后，解析时间可以减少一半。

于是尝试和嵌套/Merge有关的某些参数：
alter session set query_rewrite_enabled = false;
alter session set"_optimizer_table_expansion"=false;
alter session set "_and_pruning_enabled"=false;
alter session set "_subquery_pruning_enabled"=false;
alter session set "_optimizer_fast_access_pred_analysis" =false;
alter session set "_optimizer_sortmerge_join_enabled"   = false;
alter session set "_optimizer_sortmerge_join_inequality" = false;
............
都不管用。


这个时候，回想起最开始做的尝试：
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '9.2.0.8'; --- 0.82 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.1.0'; --- 1.03 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.2.0.1'; --- 4.03 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '11.1.0.7'; --- 12.20 seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '11.2.0.3'; --- 12.91 seconds

于是更精确的测试，然后注意到：
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.1.0.3';     ---  1.40  seconds
ALTER SESSION SET OPTIMIZER_FEATURES_ENABLE = '10.1.0.4';     ---  3.59  seconds

我们知道OPTIMIZER_FEATURES_ENABLE会控制很多和CBO有关的参数，改变OPTIMIZER_FEATURES_ENABLE其实也是在改变这些参数。很可能是这些参数在起作用。
在之前的工作中，我记得有一个参数就是10.1.0.4引入的：
_optimizer_cost_based_transformation
这个神一般的参数自从诞生之日起，带来了无数的血雨腥风，围绕它产生的问题罄竹难书。难道？？？？试验下：
alter session set "_optimizer_cost_based_transformation"=exhaustive;    ---- Elapsed: 00:00:14.11
alter session set "_optimizer_cost_based_transformation"=iterative;     ---- Elapsed: 00:00:13.71
alter session set "_optimizer_cost_based_transformation"=linear;        ---- Elapsed: 00:00:13.97
alter session set "_optimizer_cost_based_transformation"=on;            ---- Elapsed: 00:00:13.97
alter session set "_optimizer_cost_based_transformation"=off;           ---- Elapsed: 00:00:03.05

在关闭这个参数后，解析时间从10多秒锐减到3秒。

之后，一股做气，继续测试了一些调整，通过调整CBO参数继续控制和裁剪CBO的筛选范围，包括禁用在10053中看到的占有一定比例的bitmap index的推演：
alter session set "_b_tree_bitmap_plans"=false;
alter session set "optimizer_index_cost_adj" = 50;
..................

目前，此SQL解析时间已经从13秒降低到了1秒。