Waiting For KKSFBC CHILD COMPLETION?

客户有一套AIX 5.3上的10.2.0.4.5生产库系统，最近频繁出现"KKSFBC CHILD COMPLETION"等待，同时导致session不断spin消耗CPU并hang住，从表象看这似乎是由bug引起的。以KKSFBC CHILD COMPLETION为关键字到MOS查询可以找到<Bug 6795880 - Session spins / OERI after 'kksfbc child completion' wait - superceded [ID 6795880.8]>,该Bug的症状为进程不断spin且hang住、出现'KKSFBC CHILD COMPLETION'等待事件、还可能伴有'Waits for "cursor: pin S"'等待事件，直接影响的版本有11.1.0.6、10.2.0.3和10.2.0.4。 对于该Bug的描述是在发生'kksfbc child completion'等待事件后会话陷入无休止的自旋(spins)中，这种自旋(spins)发生在由堆栈调用(stack call)kksSearchChildList->kkshgnc陷入对kksSearchChildList函数的无限循环中。 就当前用户提供的版本号及等待事件信息仍不足以定位到该Bug，我们需要更详细的stack call。所幸的是这个trouble是可以重现的(reproduceable),在之后的一次案发现场我们得到了必要的信息:

Name            PID  CPU%  PgSp Owner
oracle      3723390  10.0   7.0 oracle

SQL> oradebug setospid 3723390
Oracle pid: 155, Unix process pid: 3723390, image: oracle@lmsdb1

SQL> oradebug unlimit;
Statement processed.

SQL> oradebug short_stack;
ksdxfstk+002c<-ksdxcb+04e4<-sspuser+0074<-000044F0
<-kksfbc+0b9c<-kkspsc0+0ffc<-kksParseCursor+00d4
<-opiosq0+0ae0<-kpooprx+0168<-kpoal8+0400<-opiodr+0ae0<-ttcpip+1020<-opitsk+1124
<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0098

SQL> oradebug dump processstate 10;
Statement processed.

SQL> oradebug dump systemstate 266;
Statement processed.

=========================process state dump=========================

    SO: 7000003f72e3378, type: 4, owner: 7000003f225c798, flag: INIT/-/-/0x00
    (session) sid: 270 trans: 0, creator: 7000003f225c798, flag: (41) USR/- BSY/-/-/-/-/-
              DID: 0001-009B-0000017F, short-term DID: 0000-0000-00000000
              txn branch: 0
              oct: 0, prv: 0, sql: 700000243ef9540, psql: 7000002fe76d9c0, user: 28/OLSUSER
    service name: SYS$USERS
    O/S info: user: newprepay, term: unknown, ospid: 1234, machine: newprepayC
              program: JDBC Thin Client
    application name: JDBC Thin Client, hash value=2546894660
    last wait for 'kksfbc child completion' blocking sess=0x0 seq=4397 wait_time=48840 seconds since wait started=144918
                =0, =0, =0
    Dumping Session Wait History
     for 'kksfbc child completion' count=1 wait_time=48840
                =0, =0, =0

可以从以上trace中看到会话确实曾长时间处于'kksfbc child completion'等待中，之后陷入无限自旋(spins)中消耗了大量CPU时间。但这里实际的表现又存有差异，引发无限循环的函数是kksfbc而不是kksSearchChildList(常规的调用序列是:kksParseCursor->kkspsc0->kksfbc ->kksSearchChildList->kkshgnc)。 kksfbc意为K[Kernel]K[Kompile]S[Shared]F[Find]B[Best]C[Child]该函数用以在软解析时找寻合适的子游标，在10.2.0.2以后引入了mutex互斥体来取代原有的Cursor Pin机制，Mutex较Latch更为轻量级。著名的Tanel Poder指出虽然mutex的引入改变了众多cursor pin的内部机制，但kksfbc仍需要持有library cache latches才能扫描library cache hash chains(However the traversing of library cache hash chains (the right child cursor lookup using kksfbc()) was still protected by library cache latches)。另一方面当kksfbc函数针对某个parent cursor找到合适child cursor后，可能使用KKSCHLPINx方法将该child cursor pin住，这个时候就需要exclusive地持有该child cursor相应的mutex，如:

SQL>  select mutex_addr,requesting_session rs,blocking_session bs,location from x$mutex_sleep_history;

MUTEX_ADDR               RS         BS LOCATION
---------------- ---------- ---------- ----------------------------------------
00000000A3CF8928        159        148 kksfbc [KKSCHLPIN1]
00000000A3CEA8A8        159          0 kksfbc [KKSCHLPIN1]
00000000A3CF5508        159          0 kksfbc [KKSCHLPIN1]
00000000A3CF10E8        148        159 kksLockDelete [KKSCHLPIN6]

当有一个进程执行kksfbc，而其他进程可能需要陷入'kksfbc child completion'等待中(更多的是cursor:pin S等待事件)，但这种等待一般是十分轻微的，你很难从某个"仪表"上观察到这一事件。因为一系列kksfbc相关的bug仅发生在10.2.0.2以后，可以猜测是由于mutex的引入引起的。 打破'kksfbc child completion'异常等待的一种行之有效的workaround方法是设置隐藏参数_use_kks_mutex_pin为false,即使用传统的由latch保护的Cursor pin；设置该hidden parameter需要重启实例，具体的设置方法如下:

alter system set "_kks_use_mutex_pin"=false scope=spfile;

restart instance...........

但这种方法也仅仅是行之有效，而非万试万灵。从消极的角度来说，因为放弃了mutex保护cursor pin的机制，在解析频繁的系统中library cache latch的争用将白热化，有可能成为Top 5等待事件。 另一种值得推荐的workaround是减少硬编码的SQL语句，使用session_cached_cursor减少实际的软解析操作也有助于避免引发该Bug；当然这要求我们修改代码，但从长远来看这种改良是值得的。 最后Oracle在10.2.0.4上提供了该Bug的one-off Patch 8575528,其在10.2.0.4 psu4以后的等价补丁为(Equivalent patch)为merge patch 9696904：

8557428

9696904 7527908

Both fixes are needed. 6795880 superceded by 8575528 in 9696904 which includes extra files so may cause new conflicts

但merge patch 9696904目前仅有Linux x86/64平台上的版本，而问题数据库所在平台为IBM AIX on POWER Systems (64-bit)。如果要通过补丁来fix这个问题的话，AIX平台的用户可以要求Oracle development开发部门build一个Power版的9696904 patch，也可以升级到10.2.0.5上去； 注意Patch 8575528: MISSING ENTRIES IN V$MUTEX_SLEEP.LOCATION目前有IBM AIX on POWER Systems (64-bit)平台上10.2.0.4.4的版本，经过验证该one-off patch可以在10.2.0.4 PSU4以后的版本上实施(包括10.2.0.4.5/10.2.0.4.6等)，不需要如以上描述地去apply 9696904这个merge patch。当然升级到10.2.0.5/11.1.0.7或以上版本依然有效。 此外apply以上8575528:后需要修改隐藏参数"_cursor_features_enabled"并重启才能使fix生效，具体设置防范如下:

ALTER SYSTEM SET "_cursor_features_enabled"=10 scope=spfile;
restart instance.............

注意以上参数仅在使用one-off patch时需要设置，而当通过升级到10.2.0.5/11.1.0.7来修复问题时无需设置上述"_cursor_features_enabled"参数。