【资源下载】敬勇 - 一条执行时间小于1秒的 SQL 引发的性能问题
1月13日周四晚，敬勇在云和恩墨大讲堂做了精彩的技术分享，以下为详细的内容整理：
敬勇
ACOUG, CSOUG 核心会员，Oracle Young Expert
某客户软件操作人员反应很慢不能操作，管理人员登录小机系统后发现 CPU 使用到了96%，而且这种情况持续了几个月。以下是登录后小机后载取的 topas 图，而且是周末，并没有什么人使用系统。小机是 IBM 的550，配置是2颗6核的 CPU，内存是 48G。
从 nmon 收集的磁盘 IO 来看在快照时间段(15:00到16:00)之间的磁盘 IO 并不高，因为这时根本没有什么人使用系统。
因为不在现场，要客户的管理员登录数据库执行以下脚本来查看当前数据库消耗 CPU 最多的进程在执行什么。
从上面的查询结果可以看到等待事件为 kksfbc child completion，SQLID 为 063cu7y841kmc。隔了几分钟之后再次查询，其查询如果如下:
从上面的查询结果可以看到等待事件变成了 ksdxexeotherwait，SQL ID 为 063cu7y841kmc。
kksfbc 意为 K[Kernel]K[Kompile]S[Shared]F[Find]B[Best]C[Child] 该函数用于在软解析时找寻合适的子游标，在 10.2.0.2 以后引入了 mutex 互斥体来取代原有的 Cursor Pin 机制，Mutex 较 Latch 更为轻量级。虽然 mutex 的引入改变了众多 cursor pin 的内部机制，但 kksfbc 仍需要持有 librarycache latches 才能扫描 library cache hash chains。另一方面当 kksfbc 函数针对某个 parent cursor 找到合适 childcursor 后，可能使用 KKSCHLPINx 方法将该 child cursor pin住，这个时候就需要 exclusive 地持有该 child cursor 相应的 mutex。当有一个进程执行 kksfbc，而其他进程可能需要陷入 ‘kksfbc child completion’ 等待中。
如下是查询该 SQL_ID(063cu7y841kmc) 是否存在高版本游标：
从上面的查询结果可以看到该 SQL_ID(063cu7y841kmc) 只存在一个子游标，不存在高版本游标，因此出现 kksfbc child completion，ksdxexeotherwait 等待并不是由高版本游标所造成的。
如是我猜测会不会是 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。而我这里的版本是 10.2.0.1，所以需要进一步的检查。
对于该 Bug 的描述是在发生 ‘kksfbc childcompletion’ 等待事件后会话陷入无休止的自旋 (spins) 中，这种自旋 (spins) 发生在由堆栈调用 (stackcall)kksSearchChildList->kkshgnc 陷入对 kksSearchChildList 函数的无限循环中。为了得到更详细的 stackcall，如是对系统进程 90116 进行跟踪。
SQL> oradebug setospid 90116
Oracle pid: 40, Unix process pid: 90116, image: oracleorcl@dbserv
SQL> oradebug unlimit;
Statement processed.
SQL> oradebug short_stack;
ksdxfstk+002c<-ksdxcb+04e4<-sspuser+0068<-00004750<-kksfbc+0bb0<-kkspsc0+0f3c<-kksParseCursor+00d4<-opiosq0+0b10<-kpooprx+0168<-kpoal8+0400<-opiodr+0adc<-ttcpip+1004<-opitsk+1000<-opiino+0990<-opiodr+0adc<-opidrv+0474<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0070
SQL> oradebug dump processstate 10;
Statement processed.
SQL> oradebug dump systemstate266;
Statement processed.
SQL> oradebug tracefile_name
/oracle/admin/orcl/udump/orcl_ora_90116.trc
查看生成的跟踪文件 orcl_ora_90116.trc 有如下内容:
SO: 7000001486ab188, type: 4, owner: 70000014346c5a8, flag: INIT/-/-/0x00
(session) sid: 1020 trans: 0,creator: 70000014346c5a8, flag: (41) USR/- BSY/-/-/-/-/-
DID:0000-0000-00000000, short-term DID: 0000-0000-00000000
txn branch: 0
oct: 0, prv: 0, sql:7000001473dcf10, psql: 7000001225ac0c8, user: 82/GTP2
O/S info: user: gtp-default,term: WIN-AUQ43P0UU9L, ospid: 6708:12196, machine: WORKGROUP\WIN-AUQ43P0UU9L
program: w3wp.exe
last wait for 'kksfbc child completion'blocking sess=0x0 seq=2831 wait_time=48850 seconds since wait started=572057
=0, =0, =0
Dumping Session Wait History
for 'kksfbc child completion'count=1 wait_time=48850
=0, =0, =0
从以上 trace 内容中红色部分信息可以看到会话确实曾长时间处于 ‘kksfbc childcompletion’ 等待中，之后陷入无限自旋（spins）中消耗了大量 CPU 时间。但这里实际的表现又存有差异，引发无限循环的函数是 kksfbc 而不是 kksSearchChildList（常规的调用序列是：kksParseCursor->kkspsc0->kksfbc->kksSearchChildList->kkshgnc）。
从前面的信息是 Oracle 的 BUG 的可能性极大。Oracle 在10.2.0.4上提供了该 Bug 的 one-off Patch 8575528，其在 10.2.0.4 psu4 以后的等价补丁为 (Equivalent patch) 为 merge patch 9696904：8557428 96969047527908 Both fixes are needed. 6795880superceded by 8575528 in 9696904 which includes extra files so may cause newconflicts。但 merge patch 9696904 目前仅有 Linux x86/64 平台上的版本，而问题数据库所在平台为 IBM AIX on POWERSystems (64-bit)，而且版本是 10.2.0.1。那么要解决这个问题是不是没有办法了，其实不然，我们可以将数据库从 10.2.0.1 升级到 10.2.0.5 来解决这个 BUG。
升级到 10.2.0.5 后，CPU 的使用率并虽然下降了，但还是维持在 80% 左右，这离局领导定的优化目标还远着了。
从上面的 load profile 部分可以看到每秒执行的 sql 与事务数并不高，因为是周末并没有太多人使用系统。
从上面的 top 等待事件来看主要是 CPU time，而 log file sync 的平均等待时间是 6ms，log file parallel write 的平均等待时间是 7ms，log file sync 的平均等待时间是 6ms，control file parallel write 的平均等待时间是 13ms。这些等待占 Total Call Time 的时间百分比都在百分之一以下，而且这些等待事件都属于 System I/O，与升级之前对比并没有什么变化。
ADDM 是植入 Oracle 数据库的一个自诊断引擎。ADDM 通过检查和分析 AWR 获取的数据来判断 Oracle 数据库中可能存在的问题，然后 ADDM 会定位引起性能问题的的根源，并提供解决的建议和预期能到到的改进效果。每次 AWR 快照（默认一小时一次）后，将会执行一次 ADDM 分析，分析结果存在数据库中。
ADDM 分析的执行是从上到下的。首先确定状况，然后分析找到性能问题的根源。ADDM 是用 DB time 统计来确定性能问题的。DB time 是数据库处理用户请求花费的累计时间，包括等待时间和所有非闲置的用户 session 的 CPU 时间。性能诊断的目标就是对于特定的工作量减少系统的 DB time，通过减少 DBtime，数据库使用同样的资源能够支撑更多的用户请求。ADDM 报告的问题区域指的就是显著占用了 DB time 的系统资源，它们是按照相关的 DB time 按从大到小的顺序列出的。除了诊断性能问题，ADDM 也会建议可能的解决方案，可以的话，ADDM 会推荐多种方案供选择。
如下是这个时间段的 ADDM 报告:
DETAILEDADDM REPORT FOR TASK 'TASK_72988' WITH ID 72988
--------------------------------------------------------
Analysis Period: 20-DEC-2015 from 09:00:33 to 10:00:34
DatabaseID/Instance: 1329630138/1
Database/Instance Names: ORCL/orcl
Host Name: dbserv
Database Version: 10.2.0.5.0
Snapshot Range: from 26245 to 26246
Database Time: 16644 seconds
AverageDatabase Load: 4.6 active sessions
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
FINDING 1: 93% impact (15444 seconds)
-------------------------------------
SQL statements consuming significant database time werefound.
RECOMMENDATION1: SQL Tuning, 100% benefit (38004 seconds)
ACTION: RunSQL Tuning Advisor on the SQL statement with SQL_ID
"fb44z8kbnu8wg".
RELEVANTOBJECT: SQL statement with SQL_ID fb44z8kbnu8wg and
PLAN_HASH1055903002
SELECTCOUNT(EmailDetail.F_EMAIL_DETAIL_ID) AS UnReadCount FROM
T_LK_EMAIL_EMAILGROUP EmailGroup LEFT OUTER JOIN T_LK_EMAIL_DETAIL
EmailDetail ON EmailGroup.F_EMAIL_GROUP_ID=EmailDetail.F_EMAIL_GROUP_
ID AND(EmailDetail.F_RECEIVER_ID=:param0 OR
(EmailDetail.F_SENDER_ID=:param0 AND EmailDetail.F_RECEIVER_ID IS
NULL)) ANDEmailDetail.F_EMAIL_STATE='0' AND
EmailDetail.F_RECORD_STATE='0' WHERE EmailGroup.F_PARENT_ID=0 AND
(EmailGroup.F_EMAIL_GROUP_ID!=4OR (EmailGroup.F_GROUP_TYPE='USER'
ANDEmailGroup.F_USER_ID=:param0))
ACTION:Investigate the SQL statement with SQL_ID "fb44z8kbnu8wg" for
possibleperformance improvements.
RELEVANTOBJECT: SQL statement with SQL_ID fb44z8kbnu8wg and
PLAN_HASH1055903002
SELECTCOUNT(EmailDetail.F_EMAIL_DETAIL_ID) AS UnReadCount FROM
T_LK_EMAIL_EMAILGROUP EmailGroup LEFT OUTER JOIN T_LK_EMAIL_DETAIL
EmailDetail ON EmailGroup.F_EMAIL_GROUP_ID=EmailDetail.F_EMAIL_GROUP_
ID AND(EmailDetail.F_RECEIVER_ID=:param0 OR
(EmailDetail.F_SENDER_ID=:param0 AND EmailDetail.F_RECEIVER_ID IS
NULL)) ANDEmailDetail.F_EMAIL_STATE='0' AND
EmailDetail.F_RECORD_STATE='0' WHERE EmailGroup.F_PARENT_ID=0 AND
(EmailGroup.F_EMAIL_GROUP_ID!=4 OR (EmailGroup.F_GROUP_TYPE='USER'
ANDEmailGroup.F_USER_ID=:param0))
RATIONALE:SQL statement with SQL_ID "fb44z8kbnu8wg" was executed 16029
times and hadan average elapsed time of 0.93 seconds.
FINDING 2: 76% impact (12602 seconds)
-------------------------------------
Time spent on the CPU by the instance was responsible fora substantial part
of database time.
RECOMMENDATION1: SQL Tuning, 100% benefit (38004 seconds)
ACTION: RunSQL Tuning Advisor on the SQL statement with SQL_ID
"fb44z8kbnu8wg".
RELEVANTOBJECT: SQL statement with SQL_ID fb44z8kbnu8wg and
PLAN_HASH1055903002
SELECTCOUNT(EmailDetail.F_EMAIL_DETAIL_ID) AS UnReadCount FROM
T_LK_EMAIL_EMAILGROUP EmailGroup LEFT OUTER JOIN T_LK_EMAIL_DETAIL
EmailDetail ON EmailGroup.F_EMAIL_GROUP_ID=EmailDetail.F_EMAIL_GROUP_
ID AND(EmailDetail.F_RECEIVER_ID=:param0 OR
(EmailDetail.F_SENDER_ID=:param0 ANDEmailDetail.F_RECEIVER_ID IS
NULL)) ANDEmailDetail.F_EMAIL_STATE='0' AND
EmailDetail.F_RECORD_STATE='0' WHERE EmailGroup.F_PARENT_ID=0 AND
(EmailGroup.F_EMAIL_GROUP_ID!=4 OR (EmailGroup.F_GROUP_TYPE='USER'
ANDEmailGroup.F_USER_ID=:param0))
ACTION:Investigate the SQL statement with SQL_ID "fb44z8kbnu8wg" for
possibleperformance improvements.
RELEVANTOBJECT: SQL statement with SQL_ID fb44z8kbnu8wg and
PLAN_HASH 1055903002
SELECTCOUNT(EmailDetail.F_EMAIL_DETAIL_ID) AS UnReadCount FROM
T_LK_EMAIL_EMAILGROUP EmailGroup LEFT OUTER JOIN T_LK_EMAIL_DETAIL
EmailDetail ON EmailGroup.F_EMAIL_GROUP_ID=EmailDetail.F_EMAIL_GROUP_
ID AND(EmailDetail.F_RECEIVER_ID=:param0 OR
(EmailDetail.F_SENDER_ID=:param0 AND EmailDetail.F_RECEIVER_ID IS
NULL)) ANDEmailDetail.F_EMAIL_STATE='0' AND
EmailDetail.F_RECORD_STATE='0' WHERE EmailGroup.F_PARENT_ID=0 AND
(EmailGroup.F_EMAIL_GROUP_ID!=4 OR (EmailGroup.F_GROUP_TYPE='USER'
ANDEmailGroup.F_USER_ID=:param0))
RATIONALE:SQL statement with SQL_ID "fb44z8kbnu8wg" was executed 16029
times andhad an average elapsed time of 0.93 seconds.
RATIONALE:Average CPU used per execution was 0.76 seconds.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
ADDITIONAL INFORMATION
----------------------
Wait class "Application" was not consumingsignificant database time.
Wait class "Commit" was not consumingsignificant database time.
Wait class "Concurrency" was not consumingsignificant database time.
Wait class "Configuration" was not consumingsignificant database time.
Wait class "Network" was not consumingsignificant database time.
Wait class "User I/O" was not consumingsignificant database time.
Session connect and disconnect calls were not consumingsignificant database
time.
Hard parsing of SQL statements was not consuming significantdatabase time.
The database's maintenance windows were active during 99%of the analysis
period.
The analysis of I/O performance is based on the defaultassumption that the
average read time for one database block is 10000micro-seconds.
An explanation of the terminology used in this report isavailable when you
run the report with the 'ALL' level of detail.
task_name
---------
TASK_72988
从上面的信息可以看到在快照 26245 到 26246 之间 Database Time 为 16644秒。而找到的一条 SQL 消耗了 76% 的 CPU 时间。如果对这两条 SQL 执行优化应该可以将 CPU 消耗显著降低。而该 SQL 虽然每执行一次的时间是 0.93秒，消耗的 CPU 时间有 0.76 秒。
需要优化的 SQL 语句:
SELECTCOUNT(EmailDetail.F_EMAIL_DETAIL_ID)AS UnReadCount
FROM T_LK_EMAIL_EMAILGROUP EmailGroup
LEFTOUTERJOIN T_LK_EMAIL_DETAIL EmailDetail ON EmailGroup.F_EMAIL_GROUP_ID =
EmailDetail.F_EMAIL_GROUP_ID
AND(EmailDetail.F_RECEIVER_ID =3440
OR
(EmailDetail.F_SENDER_ID =3418
AND
EmailDetail.F_RECEIVER_ID ISNULL))
ANDEmailDetail.F_EMAIL_STATE = '0'
ANDEmailDetail.F_RECORD_STATE = '0'
WHERE EmailGroup.F_PARENT_ID = 0
AND (EmailGroup.F_EMAIL_GROUP_ID != 4OR
(EmailGroup.F_GROUP_TYPE = 'USER'AND
EmailGroup.F_USER_ID = 23402));
查看其执行计划:
从执行计划来看两个表使用了 nestedloops outer 方式来进行的关联。那么要对进行优化就需要对 Oracle 表连接的类型与方法有所了解。那么这里就介绍一下外连接与嵌套循环连接。
外连接（outer join）是对内连接的一种扩展，它是指表连接的连接结果除了包含那些完全满足连接条件的记录之外还会包含驱动表中所有不满足该连接条件的记录。
外连接还分为: 左连接，右连接，全连接
左连接（left outer join）
左连接的语法为：
目标表 1 left outer join 目标表 2 on（连接条件）
或
目标表 1 left outerjoin 目标表 2 using（连接列集合）
“目标表 1 left outer join 目标表 2 on（连接条件）” 的含义为目标表 1 和目标表 2 按括号中的连接条件来做表连接，位于关键字 “left outer join” 左边的目标表 1会作为该表连接的驱动表（关键字 “left outer” 即表明位置处于 left 的表就是 outer table，这里的 outer table 就是指驱动表）。此时的连接结果除了包含目标表 1 和目标表 2 中所有满足该连接条件的记录外，还会包含驱动表（即目标表 1）中所有不满足该连接条件的记录，同时，驱动表中所有不满足该连接条件的记录所对应的被驱动表（即目标表 2）中的查询列均会以 NULL 值来填充。
右连接（right outer join）
右连接的语法为：
目标表 1 right outer join 目标表 2 on (连接条件)
或
目标表 1 right outer join 目标表 2 using (连接列集合)
“目标表 1 right outer join 目标表 2 on（连接条件）”的含义为目标表 1 和目标表 2 按括号中的连接条件来做表连接，位于关键字“right outer join”右边的目标表 2 会作为该表连接的驱动表（“right outer join”中的关键字“right outer”即表明位置处于 right 的表就是 outer table，即驱动表）。此时的连接结果除了包含目标表 1和目标表 2中所有满足该连接条件的记录外，还会包含驱动表（即目标表 2）中所有不满足该连接条件的记录，同时，驱动表中所有不满足该连接条件的记录所对应的被驱动表（即目标表1）中的查询列均会以 NULL 值来填充。
全连接（full outer join）
目标表 1 full outerjoin 目标表 2 on（连接条件）
或
目标表 1 full outer join 目标表 2 using（连接列集合）
“目标表 1 full outer join 目标表 2 on（连接条件）”的含义为目标表 1 和目标表 2 按括号中的连接条件来做表连接。此时的连接结果除了包含目标表 1 和目标表 2 中所有满足该连接条件的记录外，还会包含目标表 1 和目标表 2 中所有不满足该连接条件的记录，同时，目标表 1 和目标表 2 中所有不满足该连接条件的记录所对应的另一个表中的查询列均会以 NULL 值来填充。
嵌套循环连接
如果两个表（这里将它们分别命名为表 t1 和表 t2）在做表连接时使用的是嵌套循环连接，则 Oracle 会依次顺序执行如下步骤。
首先，优化器会按照一定的规则来决定表 t1 和 t2 中谁是驱动表，谁是被驱动表。驱动表用于外层循环，被驱动表用于内层嵌循环。这里假设驱动表是 t1，被驱动表是 t2。
接着以目标 SQL 中指定的谓词条件（如果有的话）去访问表 t1，访问驱动表 t1 后得到的结查集我们记为驱动结果集1。
然后遍历驱动结果集1并同时遍历被驱动表 t2，即先取出驱动结果集1中的第1条记录，接着遍历被驱动表 t2 并按照连接条件去判断 t2 中是否在匹配的记录，然后再取出驱动结果集1中的第2条记录，按照同样的连接条件再去遍历被驱动表 t2 并判断 t2 中是否还存在匹配的记录，直到遍历完驱动结果集1中所有的记录为止。这里的外层循环是指遍历驱动结果集1所对应的循环，内层循环是指遍历被驱动表 t2 所对应的循环。显然，外层循环所对应的驱动结果集1有多少条记录，遍历被驱动表 t2 的内层循环就要做多少次，这就是所谓的“嵌套循环”的含义。
从上述嵌套循环连接的具体执地过程可以看出：如果驱动表所对应的驱动结果集的记录数较少，同时在被驱动表的连接列上又存在唯一性索引（或者在被驱动表的连接列上存在选择性很好的非唯一性索引），那么此时使用嵌套循环连接的执行效率就会非常高；但如果驱动表所对应驱动结果集的记录数据很多，即便在这被驱动表的连接列上存在索引，此时使用嵌套循环连接的执行效率也不会高。
只要驱动结果集的记录数较少，那就具备了做嵌套循环连接的前提条件，而驱动结果集是在对驱动表应用了目标 SQL 中指定的谓词条件（如果有的话）后得到的结果集，所以大表也可以作为嵌套循环连接的驱动表，关键看目标 SQL 中指定的谓词条件（如果有的话）能否将驱动结果集的数据量降下来。
从执行计划来看该 SQL 的 cost 也不高，执行时间也就是1s（CPU 是 0.76秒），但是在并发执行次数高，而物理 CPU 数量与性能不足的情况下还是会引发性能问题。从 SQL 的执行计划来看见两个表是使用的嵌套循环，而驱动表 T_LK_EMAIL_EMAILGROUP 的数据量是接近 1w 行，T_LK_EMAIL_DETAIL 表的数量是 25w 行左右。而表 T_LK_EMAIL_EMAILGROUP 执行全表扫描后满足查询条件的记录有4条，所以就得对表 T_LK_EMAIL_DETAIL 中的记录遍历4次来找到与驱动表相匹配的记录。
表 T_LK_EMAIL_EMAILGROUP 与 T_LK_EMAIL_DETAIL 的索引结构信息如上所示，而这两个表有等值连接条件 F_EMAIL_GROUP_ID，而且在驱动表中 F_EMAIL_GROUP_ID 列是复合主键的前导列，对于主键就会存在唯一索引，所以这里选择在表 T_LK_EMAIL_DETAIL 表的 F_EMAIL_GROUP_ID 列上创建索引 createindexidx_T_LK_EMAIL_DETAIL_1 on T_LK_EMAIL_DETAIL(F_EMAIL_GROUP_ID)，创索引之后执行计划如下所示，Nestedloops outer连接的被驱动表由全表扫描变成了索引扫描。驱动表仍然是全表扫描，虽然 where 条件中存在 F_EMAIL_GROUP_ID，而且在驱动表中 F_EMAIL_GROUP_ID 列是复合主键的前导列，对于主键就会存在唯一索引，但是因为条件是 F_EMAIL_GROUP_ID!=4，这就是要查询除 F_EMAIL_GROUP_ID=4 之外的所有记录，假设表中的 F_EMAIL_GROUP_ID 从1到100，那么就要查询 99% 的数据，所以虽然存在索引还是使用的全表扫描。但是在遍历驱动表结果集的每一条记录时，扫描被驱动表不是用全表扫描而是用索引扫描性能得到了提升。
SQL 执行时间只有 0.01s 提高了10倍，优化 SQL 后小机的 CPU 使用率维护在20%左右，业务高峰期的使用率也只有 30%。
搜索盖国强（Eygle）微信号：eeygle，或者扫描下面二维码，备注：云和恩墨大讲堂，即可入群。每周与千人共享免费技术分享，与讲师在线讨论。
恩墨学院
点击原文链接下载该文档