小心，有bug:SQL开启SPM遭遇librarycache堵塞

编辑手记：在数据库中，有一些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分析

等待的参数

检查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中发现可疑目标。

篇幅原因，省略部分内容。

可以看到，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的效率。建议用户进行处理。