[20261015]模拟kksfbc child completion等待事件2.txt
--//放假前遇到的问题，系统运行缓慢，对方看到一个奇怪的等待事件kksfbc child completion，当时我就猜测可能执行的sql语句存在
--//问题。我对它印象深刻的原因，该事件没有P1，P2，P3参数。因为以前遇到过没有建表导致的情况(当时并不在现场)，该等待事件
--//kksfbc child completion并不排名靠前，也许比较少见的原因。
--//事后觉得不可思议，没有建表竟然在生产系统产生这么大的问题，根据对应的sql_id，直接查询v$sql以及v$sqlarea视图并不能获得
--//对应sql语句，要直接查x$kglob才能定位sql语句，剩下的就比较好解决，出现这类情况主要原因是sql语句无法执行，并且该语句的
--//执行密度非常大(注：没有这个条件不会出现这么严重的后果)。导致不断的执行，分析，报错，如果执行密集很低，不大会出现这类
--//情况,至少系统可以正常运行。当然还有一种可能该语句可以执行，但是产生大量子光标，许多情况下每次都要分析执行，相当于每
--//次都是硬解析，当然最主要原因是该sql语句的密集执行才有可能查询该等待事件。
--//12c以后会在alert日志记录相同执行100次以上无法执行的sql语句，建议看看alert日志，有时候我觉得非常悲催，看看我们的生产系统
--//一大堆无法执行的sql语句,当然这些题外话。
--//自己通过gdb模拟kksfbc child completion，加深对这个问题的理解。
1.环境：
SYS@book> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
$ ./lookup.awk kksfbc
kksfbc : kernel compile shared objects (cursor) find bound cursor
SYS@book> @ ev_namepr "kksfbc child completion"
==============================
EVENT# : 1448
EVENT_ID : 2679325
NAME : kksfbc child completion
PARAMETER1 :
PARAMETER2 :
PARAMETER3 :
WAIT_CLASS_ID : 1893977003
WAIT_CLASS# : 0
WAIT_CLASS : Other
DISPLAY_NAME : kksfbc child completion
CON_ID : 0
PL/SQL procedure successfully completed.
--//kksfbc child completion等待事件的p1,p2,p3显示为空。
2.学习资料：
--//参考链接：https://fritshoogland.wordpress.com/2020/04/04/oracle-library-cache-cursor-child-generation/
Whenever an Oracle database parses a SQL, it follows the following sequence of events (events which are of importance to
the topic of cursor children):
--//每当Oracle数据库解析SQL时，它遵循以下事件序列(对游标子主题重要的事件)：
1. The SQL text is hashed to generate a hash value.
2. The hash value is used to inspect the session cursor cache of the session to find a cached child.
If a cached entry is found, the child is inspected for compatibility, and then executed.
3. The hash value is used to calculate the library cache hash bucket.
4. The hash bucket is inspected, and the pointer is followed to find the parent handle.
5. In the parent handle a pointer is followed to the parent's heap 0.
6. In the parent heap 0 a pointer to the hash table with the cursor children followed.
7. The hash table is read from the most recent child down to the oldest child.
If a compatible child is found, that child is executed.
8. If no compatible child is found, a new child is created.
1. 对SQL文本进行散列以生成哈希值。
2. 哈希值用于检查会话的会话光标缓存以找到缓存的子游标。
如果发现缓存条目，则检查子条目是否兼容，然后执行。
3. 哈希值用于计算库缓存哈希桶..
4. 检查哈希桶，并跟随指针查找父手柄..
5. 在父句柄中，指针后面跟着父堆0。
6. 在父堆0中，一个指向哈希表的指针，后面跟着子游标。
7. 哈希表从最近的子游标读到最老的子游标。 --//注：以前测试21c改变查询方式。
如果找到兼容的子游标，则执行该子游标。
8. 如果没有找到兼容的子游标，则创建一个新子游标。
--//在新建子游标的过程中，链接提到一个Incomplete list的概念，大致过程概况如下：
--//1.执行kksCheckCursor看看是否有合适的子光标，如果没有执行kksSearchChildList，还是没有
--//2.执行kkshinins insert child into incomplete list，插入子光标到incomplete list,建立新的子光标，然后执行kksLoadChild
--// 建立子光标堆0。
--//在子游标加载过程中，其他会话会经历如下等待事件，直接转抄：
Child load.
--//子游标加载
Now the session that is creating a new child will continue to create the new child, for which the next step is to
allocate the child's heap 0. This is done in the function kksLoadChild(). After the child's heap 0 is allocated, it will
pin the child in exclusive mode. Sessions that were waiting for 'kksfbc child completion' now will wait for 'cursor: pin
S wait on X'. Any other sessions that scan the child list and did not find any compatible child, will run into this
(last) child and wait for 'cursor: pin S wait on X' too.
--//现在正在创建新子游标的会话将继续创建新子游标，下一步是为其分配子堆0。 这是在函数kksLoadChild()中完成的。 在分配了子
--//堆0之后，它会将子堆定位在独占模式.等待'kksfbc child completion'的会话现在将等待'cursor: pin S wait on X'。 任何其他
--//扫描子游标列表但没有找到任何兼容的子游标，都会遇到这个(最后一个)子游标，并等待'cursor: pin S wait on X'.
--//补充说明，文章提到等待事件会从'kksfbc child completion'变为'cursor: pin S wait on X'。
--//3.执行kkshindel remove child from incomplete list，删除子光标从incomplete list。
--//4.执行kkshhcins insert child into hash table，插入子光标进入hash table。
--//根据以上介绍，只要在相关函数设置断点，就可以模拟kksfbc child completion等相关等待事件。
3.测试前准备建立相关脚本:
$ cat kks.gdb
break kkshinins
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
break kksLoadChild
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
break kkshindel
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
break kkshhcins
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
$ cat kks.sql
host sleep &1
set feedback off
select sys_context ('userenv', 'sid') c10 from dual ;
@ zzdate
select * from dept where deptno=&2;
@ zzdate
set feedback 6
$ cat zzdate.sql
column c29 format a38
column c30 format a38
column c31 format a38
select
sysdate c29
,'trunc(sysdate)+'||to_char(sysdate,'hh24')||'/24+'||to_char(sysdate,'mi')||'/1440+'||to_char(sysdate,'ss')||'/86400' c30
,'"timestamp'''||to_char(sysdate,'yyyy-mm-dd hh24:mi:ss')||'''"' c31
from dual;
4.测试：
--//session 1:
SCOTT@book01p> @ spid
==============================
SID : 120
SERIAL# : 40589
PROCESS : 3459
SERVER : DEDICATED
SPID : 3461
PID : 49
P_SERIAL# : 11
KILL_COMMAND : alter system kill session '120,40589' immediate;
PL/SQL procedure successfully completed.
SCOTT@book01p> @ kks.sql 0 1
....
--//执行多次,避免一些递归sql语句的执行。
--//window 1:
$ rlgdb -f -p 3461 -x kks.gdb
....
/usr/src/debug/glibc-2.34-270.el9.x86_64/sysdeps/unix/sysv/linux/read.c:26:1001:beg:0x7f0e9f6ff282
Breakpoint 1 at 0x400ab80
Breakpoint 2 at 0x3ff0710
Breakpoint 3 at 0x400b3b0
Breakpoint 4 at 0x400ba60
(gdb)
--//session 1:
SCOTT@book01p> @ kks.sql 0 54
--//挂起！！
--//window 1,按c继续：
(gdb) c
--//session 2:
--//事先写好执行命令,在windows 1按c执行后马上切换执行如下语句：
$ seq 0 1 | xargs -IQ -P2 sqlplus -s -l scott/book@book01p @kks.sql Q 54
--//测试结果如下：
--//session 1:
SCOTT@book01p> @ kks.sql 0 54
C10
----------
120
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:44:40 trunc(sysdate)+09/24+44/1440+40/86400 "timestamp'2026-10-15 09:44:40'"
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:45:10 trunc(sysdate)+09/24+45/1440+10/86400 "timestamp'2026-10-15 09:45:10'"
--//session 2:
--//同时执行2个会话、
$ seq 0 1 | xargs -IQ -P2 sqlplus -s -l scott/book@book01p @kks.sql Q 54
C10
----------
315
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:44:42 trunc(sysdate)+09/24+44/1440+42/86400 "timestamp'2026-10-15 09:44:42'"
--//第1个会话执行zzdate的结果。
C10
----------
25
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:44:43 trunc(sysdate)+09/24+44/1440+43/86400 "timestamp'2026-10-15 09:44:43'"
--//第2个会话执行zzdate的结果，与前面相差1秒。
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:45:10 trunc(sysdate)+09/24+45/1440+10/86400 "timestamp'2026-10-15 09:45:10'"
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:45:10 trunc(sysdate)+09/24+45/1440+10/86400 "timestamp'2026-10-15 09:45:10'"
--//2个会话同时在2026-10-15 09:45:10执行完成。
--//window 1:
(gdb) c
Continuing.
Breakpoint 1, 0x000000000400ab80 in kkshinins ()
2026/10/15 09:44:40.231914018
Breakpoint 2, 0x0000000003ff0710 in kksLoadChild ()
2026/10/15 09:44:46.251427289
Breakpoint 2, 0x0000000003ff0710 in kksLoadChild ()
2026/10/15 09:44:52.280562827
Breakpoint 3, 0x000000000400b3b0 in kkshindel ()
2026/10/15 09:44:58.314814550
Breakpoint 4, 0x000000000400ba60 in kkshhcins ()
2026/10/15 09:45:04.341419426
--//每次间隔6秒。
--//session 3:
SYS@book> @ ashtop sid,BLOCKING_SESSION,sql_id,event 1=1 trunc(sysdate)+09/24+44/1440+40/86400 trunc(sysdate)+09/24+45/1440+10/86400
Total Distinct Distinct Distinct
Seconds AAS %This SID BLOCKING_SESSION SQL_ID EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------- ---------------- ------------- --------------------------- ------------------- ------------------- ---------- -------- -----------
30 1.0 30% | 120 1v6qam1u2964m 2026-10-15 09:44:40 2026-10-15 09:45:09 1 30 30
27 .9 27% | 315 120 1v6qam1u2964m library cache lock 2026-10-15 09:44:43 2026-10-15 09:45:09 1 27 27
26 .9 26% | 25 120 1v6qam1u2964m library cache lock 2026-10-15 09:44:44 2026-10-15 09:45:09 1 26 26
6 .2 6% | 5 2026-10-15 09:44:40 2026-10-15 09:44:58 1 6 6
6 .2 6% | 106 2026-10-15 09:44:41 2026-10-15 09:45:09 1 6 6
1 .0 1% | 1 os thread creation 2026-10-15 09:45:00 2026-10-15 09:45:00 1 1 1
1 .0 1% | 99 2026-10-15 09:45:03 2026-10-15 09:45:03 1 1 1
1 .0 1% | 103 control file parallel write 2026-10-15 09:44:51 2026-10-15 09:44:51 1 1 1
1 .0 1% | 103 oracle thread bootstrap 2026-10-15 09:45:00 2026-10-15 09:45:00 1 1 1
1 .0 1% | 103 2026-10-15 09:44:57 2026-10-15 09:44:57 1 1 1
10 rows selected.
--//在session 1执行到kkshinins，也就是kkshinins insert child into incomplete list时，其他会话执行出现等待事件library
--//cache lock,一直要等待session 1执行完kkshhcins insert child into hash table，插入子光标进入hash table后，其他会话才会
--//继续执行。
--//session 1开始执行时间09:44:40，session 2开始执行时间09:44:42，09:44:43，手工切换执行导致的问题，并不影响测试结果。
--//换一句话将这样情况其他会话等待时间会变长，这次测试并没有出现kksfbc child completion。
5.继续：
--//修改kks.gdb脚本，注解break kkshinins的shell sleep 6。
$ cat kks.gdb
break kkshinins
commands
shell date +"%Y/%m/%d %T.%N"
# shell sleep 6
c
end
break kksLoadChild
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
break kkshindel
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
break kkshhcins
commands
shell date +"%Y/%m/%d %T.%N"
shell sleep 6
c
end
--//再次重复前面测试，kks.sql脚本参数2选择其他值，保证该语句第1次执行，步骤略，直接贴出测试结果：
--//session 1:
SCOTT@book01p> @ kks.sql 0 55
C10
----------
120
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:28 trunc(sysdate)+09/24+57/1440+28/86400 "timestamp'2026-10-15 09:57:28'"
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:52 trunc(sysdate)+09/24+57/1440+52/86400 "timestamp'2026-10-15 09:57:52'"
--//session 2:
--//同时执行2个会话、
$ seq 0 1 | xargs -IQ -P2 sqlplus -s -l scott/book@book01p @kks.sql Q 55
C10
----------
315
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:29 trunc(sysdate)+09/24+57/1440+29/86400 "timestamp'2026-10-15 09:57:29'"
--//第1个会话执行zzdate的结果。
C10
----------
25
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:30 trunc(sysdate)+09/24+57/1440+30/86400 "timestamp'2026-10-15 09:57:30'"
--//第2个会话执行zzdate的结果，与前面相差1秒。
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:52 trunc(sysdate)+09/24+57/1440+52/86400 "timestamp'2026-10-15 09:57:52'"
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 09:57:52 trunc(sysdate)+09/24+57/1440+52/86400 "timestamp'2026-10-15 09:57:52'"
--//2个会话同时在2026-10-15 09:57:52执行完成。
--//session 1开始执行时间09:57:28，session 2开始执行时间09:57:29，09:57:30，手工切换执行导致的问题，并不影响测试结果。
--//window 1:
(gdb) c
Continuing.
Breakpoint 1, 0x000000000400ab80 in kkshinins ()
2026/10/15 09:57:28.078628239
--//没有sleep 6秒。
Breakpoint 2, 0x0000000003ff0710 in kksLoadChild ()
2026/10/15 09:57:28.083391164
Breakpoint 2, 0x0000000003ff0710 in kksLoadChild ()
2026/10/15 09:57:34.101920658
Breakpoint 3, 0x000000000400b3b0 in kkshindel ()
2026/10/15 09:57:40.121932492
Breakpoint 4, 0x000000000400ba60 in kkshhcins ()
2026/10/15 09:57:46.136968786
--//session 3:
SYS@book> @ ashtop sid,BLOCKING_SESSION,sql_id,event 1=1 trunc(sysdate)+09/24+57/1440+28/86400 trunc(sysdate)+09/24+57/1440+52/86400
Total Distinct Distinct Distinct
Seconds AAS %This SID BLOCKING_SESSION SQL_ID EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------- ---------------- ------------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
24 1.0 30% | 120 g6vc1fmk2ycjg 2026-10-15 09:57:28 2026-10-15 09:57:51 1 24 24
18 .7 23% | 25 120 g6vc1fmk2ycjg cursor: pin S wait on X 2026-10-15 09:57:34 2026-10-15 09:57:51 1 18 18
18 .7 23% | 315 120 g6vc1fmk2ycjg cursor: pin S wait on X 2026-10-15 09:57:34 2026-10-15 09:57:51 1 18 18
7 .3 9% | 106 2026-10-15 09:57:32 2026-10-15 09:57:51 1 7 7
5 .2 6% | 315 g6vc1fmk2ycjg kksfbc child completion 2026-10-15 09:57:29 2026-10-15 09:57:33 1 5 5
4 .2 5% | 25 g6vc1fmk2ycjg kksfbc child completion 2026-10-15 09:57:30 2026-10-15 09:57:33 1 4 4
1 .0 1% | 5 2026-10-15 09:57:33 2026-10-15 09:57:33 1 1 1
1 .0 1% | 9 2026-10-15 09:57:40 2026-10-15 09:57:40 1 1 1
1 .0 1% | 122 2026-10-15 09:57:29 2026-10-15 09:57:29 1 1 1
1 .0 1% | 302 2026-10-15 09:57:35 2026-10-15 09:57:35 1 1 1
10 rows selected.
--//session 1的sid=120.执行需要24秒，断点执行出现4次，4*6=24,其他因素不考虑。
--//session 2的sid=315，25，kksfbc child completion等待5，4秒，BLOCKING_SESSION显示为空。
--//session 1仅仅第1次调用kksLoadChild时，其他2个会话出现kksfbc child completion等待，调用kksLoadChild完成时，其他2个会
--//话出现等待c事件变为ursor: pin S wait on X ，需要18秒。
--//仔细看时间顺序,就很容易理解以上内容。
--//如果session 1重复执行，几乎马上完成，能查询到合适的子游标，绕过以上步骤。
SCOTT@book01p> @ kks.sql 0 55
C10
----------
120
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 10:10:40 trunc(sysdate)+10/24+10/1440+40/86400 "timestamp'2026-10-15 10:10:40'"
C29 C30 C31
-------------------------------------- -------------------------------------- --------------------------------------
2026-10-15 10:10:40 trunc(sysdate)+10/24+10/1440+40/86400 "timestamp'2026-10-15 10:10:40'"
5.补充session 2仅仅执行1个会话的情况：
SYS@book> @ ashtop sql_id,event,p1raw 1=1 trunc(sysdate)+16/24+58/1440+26/86400 trunc(sysdate)+16/24+58/1440+50/86400
Total Distinct Distinct Distinct
Seconds AAS %This SQL_ID EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------- ----------------------- ----------------- ------------------- ------------------- ---------- -------- -----------
24 1.0 51% | cpcunv1qr1wq4 2026-10-16 16:58:26 2026-10-16 16:58:49 1 24 24
18 .7 38% | cpcunv1qr1wq4 cursor: pin S wait on X 000000006D70F2C4 2026-10-16 16:58:32 2026-10-16 16:58:49 1 18 18
5 .2 11% | cpcunv1qr1wq4 kksfbc child completion 0000000000000000 2026-10-16 16:58:27 2026-10-16 16:58:31 1 5 5
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3186165/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261018]光标跟踪事件3.txt
- [20261016]光标跟踪事件2.txt
- [20261013]光标跟踪事件.txt
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
