记一次由 SQL 执行计划异常引发的高 CPU 与 cache buffers chains 竞争故障处理

一、故障背景
#

某业务系统 Oracle 11g 数据库在业务运行期间出现 CPU 使用率持续接近 100% 的情况。数据库版本为：Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production。数据库实例信息：Oracle 11g - Primary ditch，故障时间点大约在：2026-06-10 13:59 ~ 14:00，从操作系统和数据库侧观察，数据库负载明显升高，前台业务进程持续占用 CPU，业务访问存在性能风险。

二、故障现象
#

1. 操作系统 CPU 使用率接近 100%
#

现场 top 输出显示：

top - 13:59:10 up 582 days, 41 min,  2 users,  load average: 9.59, 9.26, 7.92
Tasks: 268 total,   9 running, 258 sleeping,   0 stopped,   1 zombie
Cpu(s): 99.8%us,  0.2%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

其中：99.8%us、0.0%wa。说明 CPU 主要消耗在用户态，且几乎没有 IO wait。该现象基本可以判断为数据库前台 SQL 执行消耗 CPU，而不是存储 IO 卡顿。

操作系统层面高 CPU 进程如下：

PID     USER      %CPU  COMMAND
 oracle    99.7  oracle
 oracle    99.7  oracle
 oracle    99.7  oracle
 oracle    99.3  oracle
 oracle    99.3  oracle
 oracle    96.4  oracle
 oracle    91.4  oracle
 oracle    90.7  oracle

可以看到，多个 Oracle 前台进程分别占用接近一个 CPU 核心，最终导致数据库服务器 CPU 被打满。

2. oratop 显示数据库 DB CPU 占比高
#

使用 oratop 观察数据库负载：

Oracle 11g - Primary ditch  13:59:58 up: 1.6y,   1 ins,   58 sn,   3 us,  20G mt,    5% fra,   1 er,                       111% db
ID %CPU LOAD %DCU   AAS  ASC  ASI  ASW  ASP  AST  UST MBPS IOPS IORL LOGR PHYR PHYW  %FR   PGA TEMP UTPS UCPS SSRT DCTR DWTR  %DBT
 1   99    9   99   8.9    8    2    0    0    8   58    9  328  29u 1.4M  221    1    7  362M 1.7G    0   13 294m   87   12   100

等待事件分布：

EVENT (C)                                                         TOTAL WAITS   TIME(s)  AVG_MS  PCT                    WAIT_CLASS
DB CPU                                                                         2.10E+07           76
SQL*Net message from dblink                                         1.042E+08   2187973    21.0    8                       Network
SQL*Net more data from dblink                                       4.069E+08   1749493     4.3    6                       Network
Backup: MML write backup piece                                      6.093E+08   1435440     2.4    5                Administrative
db file sequential read                                             1.309E+10   1352103     0.1    5                      User I/O

其中 DB CPU 占比 76%，与 OS 层面 99.8%us 相互印证。

3. 高负载会话集中在同一个 SQL
#

oratop 中可以看到，多个活动会话都在执行同一个 SQL_ID：

ID   SID     SPID USERNAME  PROGRAM    SRV  SERVICE  PGA  SQLID/BLOCKER OPN  E/T  STA  STE  WAIT_CLASS  EVENT/*LATCH           W/T
 165    15430 HISSCM    w3wp.exe   DED  ditch   3.5M  4ja6bgs1su89c SEL 0.5h  ACT  CPU  Concurrenc  latch: cache buffers   13m
 465    16219 HISSCM    w3wp.exe   DED  ditch   1.4M  4ja6bgs1su89c SEL 0.5h  ACT  CPU  Other       latch free             13m
   4    15680 HISSCM    w3wp.exe   DED  ditch   3.2M  4ja6bgs1su89c SEL 0.6h  ACT  CPU  Other       latch free            862u
 782    16155 HISSCM    w3wp.exe   DED  ditch   954k  4ja6bgs1su89c SEL 0.5h  ACT  CPU  Other       latch free            609u
   6    16233 HISSCM    w3wp.exe   DED  ditch   954k  4ja6bgs1su89c SEL 0.5h  ACT  CPU  Other       latch free            231u
  15    16186 HISSCM    w3wp.exe   DED  ditch   979k  4ja6bgs1su89c SEL 0.5h  ACT  CPU  Other       latch free             35u
 932    15916 HISSCM    w3wp.exe   DED  ditch   2.0M  4ja6bgs1su89c SEL 0.5h  ACT  CPU  User I/O    db file sequential re  14u
 627    15920 HISSCM    w3wp.exe   DED  ditch   3.0M  4ja6bgs1su89c SEL 0.6h  ACT  CPU  User I/O    db file sequential re  12u

初步判断：

故障 SQL_ID：4ja6bgs1su89c 数据库用户：HISSCM 应用程序：w3wp.exe 来源机器：WORKGROUP\YYGYL-DB-VSS-NE 主要等待：latch free / latch: cache buffers chains

说明问题集中在 IIS/.NET 应用 w3wp.exe 发起的某个 SQL 上。

三、分析过程
#

1. 通过 OS SPID 定位数据库会话
#

根据 top 中的 Oracle 进程号，执行以下 SQL 定位数据库会话：

set lines 300 pages 100
col username for a15
col program for a25
col machine for a30
col module for a30
col event for a35
col sql_id for a15

select s.sid,
       s.serial#,
       p.spid,
       s.username,
       s.machine,
       s.program,
       s.module,
       s.status,
       s.sql_id,
       s.sql_child_number,
       s.event,
       s.state,
       s.last_call_et
from v$session s
join v$process p
  on s.paddr = p.addr
where p.spid in ('15680','15920','16219','15430','16233','16155','16186','15916')
order by s.last_call_et desc;

查询结果：

SID  SERIAL#  SPID   USERNAME  MACHINE                    PROGRAM   MODULE   STATUS  SQL_ID          SQL_CHILD_NUMBER EVENT                       STATE              LAST_CALL_ET
---  -------  -----  --------  -------------------------- --------- -------- -------- --------------- ---------------- --------------------------- ------------------ ------------
  64439    15680  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED SHORT TIME  2210
51801    15920  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED KNOWN TIME  2100
13197    15430  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED SHORT TIME  2016
26869    15916  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED SHORT TIME  1989
 32425    16186  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED SHORT TIME  1905
401      16155  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED SHORT TIME  1879
48709    16219  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch: cache buffers chains WAITED SHORT TIME 1768
  48513    16233  HISSCM    WORKGROUP\YYGYL-DB-VSS-NE  w3wp.exe  w3wp.exe ACTIVE   4ja6bgs1su89c   21               latch free                 WAITED KNOWN TIME  1709

结论：

8 个高 CPU Oracle 前台进程，全部执行 SQL_ID=4ja6bgs1su89c，且全部为 child_number=21。

这一步将问题范围从“数据库整体 CPU 高”缩小到“单条 SQL 的某个 child cursor 异常”。

2. 查看 SQL 执行统计
#

执行以下 SQL 查看该 SQL_ID 的所有 child cursor：

set long 200000
set lines 300 pages 100
col sql_text for a120

select sql_id,
       child_number,
       plan_hash_value,
       executions,
       elapsed_time/1000000 elapsed_s,
       cpu_time/1000000 cpu_s,
       buffer_gets,
       disk_reads,
       rows_processed,
       parse_calls,
       loads
from v$sql
where sql_id = '4ja6bgs1su89c'
order by child_number;

关键结果如下：

SQL_ID          CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS  ELAPSED_S      CPU_S BUFFER_GETS DISK_READS ROWS_PROCESSED
--------------- ------------ --------------- ---------- ---------- ---------- ----------- ---------- --------------
4ja6bgs1su89c              1       209089688         18   2.893776   2.207665     1193342       4837             18
4ja6bgs1su89c              2       209089688         26   3.515837   2.817574     1650474       5546             26
4ja6bgs1su89c              3       209089688         23   3.032803   2.451626     1448162       4019             23
...
4ja6bgs1su89c             17       209089688         76   5.101620   4.734278     2887103       7876             76
...
4ja6bgs1su89c             21      3976293346         10 17736.2609 16541.4603  2973986803     293276              2
...
4ja6bgs1su89c             24       209089688         54   9.888483   9.296582     7073602       8043             54

从结果看，绝大多数 child cursor 的执行时间只有几秒，逻辑读在几十万到几百万之间；而 child_number=21 明显异常：

child_number    = 21
plan_hash_value = 3976293346
executions      = 10
elapsed_s       = 17736.2609
cpu_s           = 16541.4603
buffer_gets     = 2973986803
disk_reads      = 293276
rows_processed  = 2

也就是说，child 21 只执行了 10 次，却消耗了约 1.65 万秒 CPU，产生了约 29.7 亿逻辑读，最终只处理了 2 行结果。

这说明问题不是业务返回数据量大，而是执行路径极其低效。

3. 查看 SQL 文本
#

执行：

set long 200000
set pages 0

select sql_fulltext
from v$sql
where sql_id = '4ja6bgs1su89c'
  and rownum = 1;

SQL 文本如下：

select count(:areaid||:cstid||:csttype||:empid)
from SCM_SALINV_V
where 1=1
  and areaid=:areaid
  and dealid=:cstid
  and invoicedate>=to_date(:invoicedate564 ,'yyyy-mm-dd')

该 SQL 是一个基于视图 SCM_SALINV_V 的计数查询，核心过滤条件为：

areaid = :areaid
dealid = :cstid
invoicedate >= to_date(:invoicedate564, 'yyyy-mm-dd')

其中 count(:areaid||:cstid||:csttype||:empid) 写法没有实际必要，建议后续应用侧改为：

select count(*)
from SCM_SALINV_V
where areaid=:areaid
  and dealid=:cstid
  and invoicedate>=to_date(:invoicedate564 ,'yyyy-mm-dd')

4. 对比好计划与坏计划
#

执行：

set lines 300 pages 300

select *
from table(dbms_xplan.display_cursor(
  '4ja6bgs1su89c',
  null,
  'ALLSTATS LAST +PEEKED_BINDS +OUTLINE +ALIAS +NOTE'
));

好计划主要为：

Plan hash value: 209089688

| Id  | Operation                           | Name                       |
|*  9 | TABLE ACCESS FULL                   | PUB_TRANCODE               |
|* 10 | TABLE ACCESS BY INDEX ROWID         | SCM_SALINV                 |
|* 11 | INDEX RANGE SCAN                    | IDX_SCM_SALINV_INVOICEDATE |
|* 12 | TABLE ACCESS FULL                   | PUB_HOSPITAL               |
|* 14 | INDEX RANGE SCAN                    | IDX_PUB_HOSDEA_REL_HOSID   |

好计划的特点：

SCM_SALINV 使用 IDX_SCM_SALINV_INVOICEDATE。
先利用 INVOICEDATE 做日期范围过滤。
配合 HASH JOIN，整体执行时间较短。

坏计划为：

Plan hash value: 3976293346

| Id  | Operation                           | Name                     | E-Rows |
|   0 | SELECT STATEMENT                    |                          |        |
|   1 | SORT AGGREGATE                      |                          |      1 |
|   2 | NESTED LOOPS                        |                          |      1 |
|   3 | NESTED LOOPS                        |                          |      1 |
|   4 | NESTED LOOPS                        |                          |      1 |
|   5 | NESTED LOOPS                        |                          |      1 |
|   6 | NESTED LOOPS                        |                          |      1 |
|   7 | NESTED LOOPS                        |                          |      1 |
|   8 | NESTED LOOPS                        |                          |      1 |
|*  9 | INDEX SKIP SCAN                     | PK_PUB_TRANSCODE         |      1 |
|* 10 | TABLE ACCESS BY INDEX ROWID         | SCM_SALINV               |      1 |
|* 11 | INDEX RANGE SCAN                    | IDX_SCM_SALINV_DEALID    |      1 |

坏计划的问题：

使用 PK_PUB_TRANSCODE 做 INDEX SKIP SCAN。
后续通过 Nested Loops 驱动 SCM_SALINV。
SCM_SALINV 访问路径选择了 IDX_SCM_SALINV_DEALID。
由于 DEALID=1 数据量极大，导致访问大量无效数据。
大量逻辑读引发 CPU 飙升和 latch: cache buffers chains 竞争。

5. 查询 child 21 的绑定变量
#

执行：

set lines 300 pages 100
col name for a20
col datatype_string for a20
col value_string for a50
col last_captured for a20

select sql_id,
       child_number,
       name,
       position,
       datatype_string,
       value_string,
       to_char(last_captured,'yyyy-mm-dd hh24:mi:ss') last_captured
from v$sql_bind_capture
where sql_id = '4ja6bgs1su89c'
  and child_number = 21
order by position;

结果：

SQL_ID          CHILD_NUMBER NAME             POSITION DATATYPE_STRING VALUE_STRING LAST_CAPTURED
--------------- ------------ ---------------- -------- --------------- ------------ --------------------
4ja6bgs1su89c             21 :AREAID                 1 NUMBER          1            2026-06-10 13:24:04
4ja6bgs1su89c             21 :CSTID                  2 NUMBER          1            2026-06-10 13:24:04
4ja6bgs1su89c             21 :CSTTYPE                3 NUMBER
4ja6bgs1su89c             21 :EMPID                  4 NUMBER
4ja6bgs1su89c             21 :AREAID                 5 NUMBER          1            2026-06-10 13:24:04
4ja6bgs1su89c             21 :CSTID                  6 NUMBER          1            2026-06-10 13:24:04
4ja6bgs1su89c             21 :INVOICEDATE564         7 VARCHAR2(32)    2026-06-09   2026-06-10 13:24:04

因此，child 21 对应的实际过滤条件为：

areaid = 1
dealid = 1
invoicedate >= to_date('2026-06-09','yyyy-mm-dd')

6. 验证数据分布与选择性
#

先查询 SCM_SALINV 表整体分布：

select count(*) total_cnt,
       count(distinct dealid) dealid_ndv,
       count(distinct areaid) areaid_ndv,
       count(distinct trunc(invoicedate)) date_ndv
from HISSCM.SCM_SALINV;

结果：

TOTAL_CNT  DEALID_NDV  AREAID_NDV  DATE_NDV
---------  ----------  ----------  --------
4495927    7           1           374

说明：

SCM_SALINV 总行数约 449 万。
DEALID 只有 7 个不同值。
AREAID 只有 1 个不同值。
INVOICEDATE 有 374 个不同日期。

接着验证 child 21 绑定值的选择性：

select count(*)
from HISSCM.SCM_SALINV
where dealid = 1;

结果：

COUNT(*)
----------
3600971

继续增加 areaid=1 条件：

select count(*)
from HISSCM.SCM_SALINV
where dealid = 1
  and areaid = 1;

结果：

COUNT(*)
----------
3600971

说明 areaid=1 没有过滤效果。

最后增加日期条件：

select count(*)
from HISSCM.SCM_SALINV
where dealid = 1
  and areaid = 1
  and invoicedate >= to_date('2026-06-09','yyyy-mm-dd');

结果：

COUNT(*)
----------
9737

该结果非常关键：

dealid = 1                              命中 3600971 行
dealid = 1 and areaid = 1               仍然命中 3600971 行
再加 invoicedate >= 2026-06-09          只剩 9737 行

说明：

DEALID=1 是大倾斜值，选择性很差。
AREAID=1 没有过滤效果。
真正有效的过滤条件是 INVOICEDATE。

因此，坏计划使用 IDX_SCM_SALINV_DEALID 是导致高 CPU 的核心原因。

四、故障根因
#

本次故障的直接原因是：SQL_ID=4ja6bgs1su89c 生成了多个 child cursor，其中 child_number=21 选择了错误执行计划 plan_hash_value=3976293346。

错误计划的主要问题：

使用 PK_PUB_TRANSCODE 做 INDEX SKIP SCAN。
通过 Nested Loops 访问 SCM_SALINV。
SCM_SALINV 使用 IDX_SCM_SALINV_DEALID。
绑定变量 CSTID=1，即 DEALID=1，而该条件命中约 360 万行。
日期条件 INVOICEDATE>=2026-06-09 实际只返回 9737 行，但坏计划没有优先使用日期过滤。
大量无效逻辑读导致 CPU 99%，并伴随 latch free / latch: cache buffers chains。

根因可以总结为：绑定变量取值存在数据倾斜，优化器生成了不适合当前绑定值的执行计划。错误计划选择低选择性 DEALID 索引，导致 SCM_SALINV 大量逻辑读和 CPU 消耗。

五、处理过程
#

1. 固定好执行计划
#

在处理前查询 SQL Plan Baseline：

select sql_handle,
       plan_name,
       enabled,
       accepted,
       fixed,
       origin
from dba_sql_plan_baselines
where sql_text like '%SCM_SALINV_V%'
order by created desc;

结果：

no rows selected

说明当时还没有 SQL Plan Baseline。

将好计划 plan_hash_value=209089688 从 cursor cache 加载为固定计划：

declare
  l_plans number;
begin
  l_plans := dbms_spm.load_plans_from_cursor_cache(
               sql_id          => '4ja6bgs1su89c',
               plan_hash_value => 209089688,
               fixed           => 'YES',
               enabled         => 'YES');
  dbms_output.put_line('Loaded plans: ' || l_plans);
end;
/

执行结果：

PL/SQL procedure successfully completed.

再次查看 Baseline：

select sql_handle,
       plan_name,
       enabled,
       accepted,
       fixed,
       origin
from dba_sql_plan_baselines
where sql_text like '%SCM_SALINV_V%'
order by created desc;

结果：

SQL_HANDLE                     PLAN_NAME                      ENA ACC FIX ORIGIN
------------------------------ ------------------------------ --- --- --- --------------
SQL_25c9cd0351ce2f2c           SQL_PLAN_2bkfd0d8wwbtc3cef7efc YES YES YES MANUAL-LOAD

说明好计划已经被固定。

2. 清理坏 child cursor
#

查询坏计划 child 21 的地址和 hash value：

select child_number,
       address,
       hash_value,
       plan_hash_value
from v$sql
where sql_id = '4ja6bgs1su89c'
  and child_number = 21;

结果：

CHILD_NUMBER ADDRESS          HASH_VALUE PLAN_HASH_VALUE
------------ ---------------- ---------- ---------------
21           00000005569B6108   59580716      3976293346

执行 purge命令后成功：

exec sys.dbms_shared_pool.purge('00000005569B6108,59580716','C');

结果：

PL/SQL procedure successfully completed.

需要注意的是，dbms_shared_pool.purge 可以清理 cursor 对象，防止后续复用坏计划，但不能中断已经在执行的 SQL。对于已经运行中的 child 21 会话，仍需要等待其结束或手工 kill session。

3. 创建复合索引
#

基于数据分布，当前 SQL 的关键条件为：

dealid = :cstid
areaid = :areaid
invoicedate >= :invoicedate564

因此创建复合索引：

create index HISSCM.IDX_SCM_SALINV_DA_DATE
on HISSCM.SCM_SALINV(DEALID, AREAID, INVOICEDATE)
online;

执行结果：

Index created.

虽然 AREAID 只有一个不同值，选择性较低，但由于 SQL 条件中包含 dealid + areaid + invoicedate，该复合索引可以支持当前 SQL 通过等值条件加范围条件访问数据，避免只按 DEALID 扫描 360 万行。

4. 收集统计信息
#

索引创建完成后，立即收集表和索引统计信息：

begin
  dbms_stats.gather_table_stats(
    ownname          => 'HISSCM',
    tabname          => 'SCM_SALINV',
    estimate_percent => dbms_stats.auto_sample_size,
    method_opt       => 'FOR ALL COLUMNS SIZE AUTO',
    cascade          => true,
    degree           => 4
  );
end;
/

执行结果：

PL/SQL procedure successfully completed.

六、处理后验证
#

处理后再次查询 SQL 执行统计：

select child_number,
       plan_hash_value,
       executions,
       elapsed_time/1000000 elapsed_s,
       cpu_time/1000000 cpu_s,
       buffer_gets,
       disk_reads,
       rows_processed
from v$sql
where sql_id = '4ja6bgs1su89c'
order by child_number;

结果：

CHILD_NUMBER PLAN_HASH_VALUE EXECUTIONS  ELAPSED_S      CPU_S BUFFER_GETS DISK_READS ROWS_PROCESSED
------------ --------------- ---------- ---------- ---------- ----------- ---------- --------------
0            209089688        2          .621105    .270959      112899        340              2
21           3976293346       10         26146.5052 24319.4699   68099814      293351           2

可以看到，新生成的 child 0 已经使用好计划：

plan_hash_value = 209089688
executions      = 2
elapsed_s       = 0.621105
cpu_s           = 0.270959
buffer_gets     = 112899

而旧的 child 21 仍然是坏计划：

plan_hash_value = 3976293346

这说明：

Baseline 已经对新解析生效。
新执行已开始走好计划。
已在执行的旧 child 21 会话不会因为 purge 自动中断，需要单独处理。

七、应急 kill 语句
#

对于已经运行很久的旧 child 21 会话，如果业务允许，可以执行：

alter system kill session '4,64439' immediate;
alter system kill session '627,51801' immediate;
alter system kill session '165,13197' immediate;
alter system kill session '932,26869' immediate;
alter system kill session '15,32425' immediate;
alter system kill session '782,401' immediate;
alter system kill session '465,48709' immediate;
alter system kill session '6,48513' immediate;

如果会话处于 KILLED 状态长时间不释放，可以从 OS 层处理对应 SPID：

kill -9 15680
kill -9 15920
kill -9 15430
kill -9 15916
kill -9 16186
kill -9 16155
kill -9 16219
kill -9 16233

注意：OS 层 kill -9 属于强制手段，应在确认这些会话是可中断查询后再执行。

八、总结
#

本次故障是由 SQL_ID=4ja6bgs1su89c 的 child 21 选择错误执行计划导致，最终通过固定好计划、清理坏游标、创建复合索引并收集统计信息恢复稳定。

一、故障背景#

二、故障现象#

1. 操作系统 CPU 使用率接近 100%#

2. oratop 显示数据库 DB CPU 占比高#

3. 高负载会话集中在同一个 SQL#

三、分析过程#

1. 通过 OS SPID 定位数据库会话#

2. 查看 SQL 执行统计#

3. 查看 SQL 文本#

4. 对比好计划与坏计划#

5. 查询 child 21 的绑定变量#

6. 验证数据分布与选择性#

四、故障根因#

五、处理过程#

1. 固定好执行计划#

2. 清理坏 child cursor#

3. 创建复合索引#

4. 收集统计信息#

六、处理后验证#

七、应急 kill 语句#

八、总结#

一、故障背景
#

二、故障现象
#

1. 操作系统 CPU 使用率接近 100%
#

2. oratop 显示数据库 DB CPU 占比高
#

3. 高负载会话集中在同一个 SQL
#

三、分析过程
#

1. 通过 OS SPID 定位数据库会话
#

2. 查看 SQL 执行统计
#

3. 查看 SQL 文本
#

4. 对比好计划与坏计划
#

5. 查询 child 21 的绑定变量
#

6. 验证数据分布与选择性
#

四、故障根因
#

五、处理过程
#

1. 固定好执行计划
#

2. 清理坏 child cursor
#

3. 创建复合索引
#

4. 收集统计信息
#

六、处理后验证
#

七、应急 kill 语句
#

八、总结
#