编辑手记：在数据库中，有一些bug,可能并不会造成严重的故障，却在细节上影响系统的性能，而你可能并不知情。
情景描述
在客户系统中，某一条SQL的执行总是会遭遇librarycache堵塞。时间为3-15分钟不等。
以下是dba_hist_active_sess_history的里相关的信息：
COUNT(*) P3 TO_CHAR(SAMPL
------ --------- ------------------
3 520003 20161118 1049
2792 520002 20161118 1049
…
215 520002 20161118 1052
1 310003 20161201 1049
1 310002 20161201 1049
3 520003 20161214 1049
908 520002 20161214 1049
2 520003 20161214 1050
4876 520002 20161214 1050
…
1 520003 20161214 1057
938 520002 20161214 1057
2 520003 20161227 1049
6551 520002 20161227 1049
3 520003 20161227 1050
8245 520002 20161227 1050
…
1 520003 20161227 1059
3205 520002 20161227 1059
1 520003 20170102 2249
3034 520002 20170102 2249
…
2 520003 20170102 2303
4362 520002 20170102 2303
可以发现一个奇怪的现象，每次出现都是在10:49开始，持续几分钟, 上午或者晚上， 无一例外。
Librarycache分析
等待的参数
Event | % Event | P1 Value, P2 Value, P3 Value | % Activity |
library cache lock | 58.13 | "479334793648","480850481424","5373954" | 0.04 |
library cache: mutex X | 40.33 | "2124281552","67461051318272","82" | 1.05 |
library cache: mutex X | 40. | "2124281552","66481798774784","82" | 1.04 |
library cache: mutex X | 40. | "2124281552","37323265802240","82" | 1.04 |
检查libcache内部表，发现等待的SQL的hash_value 2124281552， namespace为SQL AREA BUILD。锁模式为少数几个独占锁(P3: 0003)和大量的共享锁(P3: 0002)。
该SQL详情如下：
select lpad(to_char(479334793648,'FMXXXXXXXXXXXXXXXX'),16,'0') HDR,
floor(5373954/65536),KGLSTDSC, mod(5373954,65536) from x$kglst
where kglsttyp = 'NAMESPACE' and KGLSTIDN = floor(5373954/65536);
HDR FLOOR(5373954/65536) KGLSTDSC MOD(5373954,65536)
0000006F9A9481B0 82 SQL AREA BUILD
2 -- 2：Row-S 行共享(RS)
ADDR KGLHDADR KGLHDPAR
---------------- ---------------- ----------------
KGLNAOBJ KGLNAHSH KGLHDNSD KGLHDOBJ
----------------- ---------- ----------------- ----------------
00007F9E2E152A40 0000006F9A9481B0 0000006F9A9481B0
8a954ac25948a0e4 2124281552 SQL AREA BUILD 00
从v$db_object_cache上看，NAMESPACE='SQLAREA BUILD'集中在这个SQL(2124281552), 其他对象几乎没有.
SQL> l
1 select owner||'.'||name,LOCKED_TOTAL,HASH_VALUE,NAMESPACE
2 from v$db_object_cache
3 where LOCKED_TOTAL > 1e4 and NAMESPACE='SQL AREA BUILD'
4* order by 2 desc
OWNER||'.'||NAME
-----------------------------------------
LOCKED_TOTAL HASH_VALUE NAMESPACE
------------ ---------- -----------------
$BUILD$.8a954ac25948a0e4
980338 2124281552 SQL AREA BUILD
$BUILD$.8d3a2b6c82e1f24a
19551 838677984 SQL AREA BUILD;
Library cache效率
SQL> l
1 select * from (
2 select instance_number,snap_id,NAMESPACE,
gets - lag(gets) over(partition by instance_number,NAMESPACE order by snap_id ) gets,
gethits - lag(gethits) over(partition by instance_number,NAMESPACE order by snap_id ) gethits
3 from
4 dba_hist_librarycache where NAMESPACE = 'SQL AREA BUILD'
5* ) where gets > 1e3
SQL> c/3/4
5* ) where gets > 1e4
SQL>
SNAP_ID 1-GETHITS/GETS GETS GETHITS
------- -------------- ------- --------
29037 .818992528 4149 751
29223 .180594901 15532 12727
29223 .003631652 446078 444458
29229 .92168512 7406 580
29817 .842255412 5959 940
29818 .496903641 4037 2031
29847 .003819032 332545 331275
29853 .877702162 4996 611
30148 .863040311 4118 564
30150 .90610175 6113 574
30163 .816539263 4317 792
30164 .339652956 6224 4110
30164 .003373041 769039 766445
30165 .001798013 219687 219292
30184 .859574468 4465 627
30185 .543539326 7832 3575
30185 .474295506 5252 2761
30186 .658835375 5959 2033
30187 .703128195 4891 1452
30189 .895012469 4010 421
请求和命中同步上涨，发现并非由于MISS造成的问题。
SQL AREA BUILD是一个非常罕见的LIBRARY 操作。毫无疑问，SQL AREA BUILD是这个故障的最关键信息之一，
SQL分析
SQLID: 8p5aas9cnj874
SQLTEXT:
SELECT F.REFOPCODE, NVL(F.EATTRIBUTE3, 'N'), F.TSID FROM (SELECT S.REFOPCODE, S.EATTRIBUTE3, S.TSID FROM TBLTS S WHERE S.RCARD = :B4 AND S.CDATE = :B3 AND S.ORGID = :B2 AND S.RCARDSEQ = :B1 AND S.TSSTATUS = 'tsstatus_reflow' ORDER BY S.MTIME DESC) F WHERE ROWNUM = 1
Version Count
SQL> select count(*) from v$sql where sql_id = '8p5aas9cnj874';
COUNT(*)
----------
17
该SQL Version 为17，不算太高。
SQL执行趋势
SNAP_ID LOADED VERSIONS VERSION
COUNT INVALIDATIONS
DELTA LOADS
DELTA PARSE_CALLS
DELTA EXECUTIONS_DELTA
30167 7 11 5 11 20192 318672
30167 9 13 17 23 19996 118173
30166 7 11 5 11 19603 354010
30166 9 13 16 21 19627 107652
30165 9 13 16 19 5936 18983
30165 6 11 3 8 5229 89726
30164 6 11 3 8 2526 110558
30164 3 9 0 0 121 80
30163 7 7 5 9 26875 352589
30163 7 7 5 10 26925 338666
30162 7 7 5 9 26343 340612
30162 7 7 5 10 26324 325503
30161 7 7 4 9 26213 309335
30161 7 7 5 9 26526 326526
30160 7 7 3 6 23104 277292
30160 7 7 5 10 23348 273669
30159 7 7 5 9 17877 209221
30159 7 7 4 8 17748 214364
30158 7 7 6 11 19152 230054
故障期间，执行次数/parse call反而下降，证明并非由于SQL执行量或者parse call量增加导致问题。
SQL执行计划
PLAN_TABLE_OUTPUT
-----------------------------------------------
SQL_ID 8p5aas9cnj874, child number 2
-------------------------------------
SELECT F.REFOPCODE, NVL(F.EATTRIBUTE3, 'N'), F.TSID FROM (SELECT
S.REFOPCODE, S.EATTRIBUTE3, S.TSID FROM TBLTS S WHERE S.RCARD = :B4 AND
S.CDATE = :B3 AND S.ORGID = :B2 AND S.RCARDSEQ = :B1 AND S.TSSTATUS =
'tsstatus_reflow' ORDER BY S.MTIME DESC) F WHERE ROWNUM = 1
Plan hash value: 427499170
可以发现，SQL没有使用特殊函数，但采用了SPM.
时间点分析
问题发生的时间点规律性非常强，总共出过5次，4次在上午10:49, 一次在晚上10:49, 从未有过例外。因此，有足够的理由怀疑，这个故障由一个周期性执行的activity所诱发。因此，我们检查了操作系统crontab, 应用定时任务，数据库DBA_JOB和数据库DBA_SCHEDUEL_JOB等，只在DBA_SCHEDUEL_JOB中发现可疑目标。
JoB ID | Log Date | Job Name |
51932 | 20161204 104946 | RLM$EVTCLEANUP. |
51982 | 20161204 224946 | RLM$EVTCLEANUP. |
52028 | 20161205 104946 | RLM$EVTCLEANUP. |
52072 | 20161205 224946 | RLM$EVTCLEANUP. |
52694 | 20161213 104946 | RLM$EVTCLEANUP. |
52723 | 20161213 224946 | RLM$EVTCLEANUP. |
52768 | 20161214 104946 | RLM$EVTCLEANUP. |
52814 | 20161214 224946 | RLM$EVTCLEANUP. |
53152 | 20161218 104946 | RLM$EVTCLEANUP. |
53214 | 20161218 224946 | RLM$EVTCLEANUP. |
53259 | 20161219 104946 | RLM$EVTCLEANUP. |
53289 | 20161219 224946 | RLM$EVTCLEANUP. |
53335 | 20161220 104946 | RLM$EVTCLEANUP. |
53739 | 20161225 104946 | RLM$EVTCLEANUP. |
53808 | 20161225 224946 | RLM$EVTCLEANUP. |
54111 | 20161229 104946 | RLM$EVTCLEANUP. |
篇幅原因，省略部分内容。
可以看到，Schedule Job RLM$EVTCLEANUP. 在每个小时的49分会开始运行。根据Oracle官方文档，RLM$EVTCLEANUP属于EXFSYS用户，专门用户XML数据库的数据过滤功能。由于客户数据库未使用XML DB及其相关的数据过滤功能，因此，可以考虑删除该用户。
寻找对应BUG
从Oracle官方网站寻找关于“SQL AREA BUILD”的BUG. 找到以下文章。
Bug: 16005481: PLAN FOR HINTED SQL LINKED TO UNHINTED SQL IN SPM AND HIGH 'LIBRARY CACHELOCK'.
该BUG首先发现于11.2.0.3.0，但从未被修复。
官网的示例如下：
整体故障现象，library cache, SPM 以及版本11.2.0.3.0都比较接近。
解决方案
根据以上分析，Bug 16005481及EXFSYS的RLM$EVTCLEANUP的定时任务最为可疑，因此，建议进行以下操作：
移除该SQL的SPM, 并改用hint保证SQL性能。
修改初始化参数 skip_unusable_indexes=false
移除疑似1049 AM/1049 PM出现的活动的EXFSYS用户，此用户为Oracle 访问XML相关的一个用户，在目前应用中没有使用。
后续建议：
11.2.0.4.0 为11g最后一个大的patchset,但还是存在不少bug, 建议用户有机会可以升级到11.2.0.4.161118， 里面包含了大量的bug fix.
在AWR中可以发现数据库中存在大量failed parse, 这些failed parse 可能影响library cache的效率。建议用户进行处理。
加入"云和恩墨大讲堂"，参与讨论学习
搜索 盖国强（Eygle）微信号：eyygle，或者扫描下面二维码，备注：云和恩墨大讲堂，即可入群。每周与千人共享免费技术分享，与讲师在线讨论。
