某次数据库CPU使用率在无人工干预下从920到945分之间突然升至近100%，后自动降至正常。分析发现是Oracle优化器对特定视图和表基数评估错误导致执行计划不当，消耗大量CPU。错误执行计划在多次运行后，Oracle 11G的cardinality feedback功能自动修正了执行计划，降低了CPU使用。建议对错误SQL语句使用SQL_PROFILE固定执行计划以防止类似问题再次发生。
1、CPU接近100% nmon数据 8月5日在9：209：40之间，出现CPU接近100%的情况，特点表现为9：20左右CPU急剧攀升，在9：45左右又快速下降 2、原因分析结果总述 2.1 持续时间与恢复方式 此次CPU攀高时间持续约20分钟，在无人工干预的情况下自动恢复 2.2 原因分析
1、CPU接近100% nmon数据
8月5日在9：20—9：40之间，出现CPU接近100%的情况，特点表现为9：20左右CPU急剧攀升，在9：45左右又快速下降
2、原因分析结果总述
2.1 持续时间与恢复方式
此次CPU攀高时间持续约20分钟，在无人工干预的情况下自动恢复
2.2 原因分析总述：
经过分析，原因为：4条SQL语句ORACLE优化器对LB_T_XXXVIDER视图、LB_T_XXXJECT_PROVIDER表、LA_XXCKAGE表的基数数据评估发生了巨大的差错，导致选择了错误的执行计划，消耗大量的CPU资源
2.3 错误执行计划估算数据与正确执行计划估算数据对比
此处为选择一条最严重的SQL语句为例，其它语句原因相同
错误执行计划基数估算值
Execution Plan
Id
Operation
Name
Rows
Bytes
Cost (%CPU)
0
SELECT STATEMENT
315 (100)
1
COUNT STOPKEY
2
VIEW
1
180
315 (2)
3
SORT ORDER BY STOPKEY
1
151
315 (2)
4
HASH UNIQUE
1
151
314 (1)
5
FILTER
6
NESTED LOOPS OUTER
1
151
313 (1)
7
NESTED LOOPS
1
86
35 (0)
8
TABLE ACCESS BY INDEX ROWID
LB_T_XXXJECT_PROVIDER
1
61
34 (0)
9
INDEX RANGE SCAN
IDX_LB_T_XXXJECT_PROVIDER_003
183
3 (0)
10
TABLE ACCESS BY INDEX ROWID
LA_XXCKAGE
1
25
1 (0)
11
INDEX UNIQUE SCAN
PK_LA_XXCKAGE
1
0 (0)
12
VIEW PUSHED PREDICATE
LB_T_XXXVIDER
1
65
278 (1)
13
MERGE JOIN OUTER
1
64
278 (1)
14
TABLE ACCESS BY INDEX ROWID
XXCC_SUPPLIER
1
45
146 (0)
15
INDEX FULL SCAN
PK_XXCC_SUPPLIER
1
145 (0)
16
SORT JOIN
17998
333K
132 (2)
17
VIEW
17998
333K
131 (1)
18
SORT GROUP BY
17998
544K
131 (1)
19
TABLE ACCESS FULL
XXCC_SUPPLIER_CONTACT
30058
909K
130 (0)
正确执行计划基数估算值
Execution Plan
Id
Operation
Name
Rows
Bytes
Cost (%CPU)
0
SELECT STATEMENT
64460 (100)
1
COUNT STOPKEY
2
VIEW
224K
38M
64460 (1)
3
SORT ORDER BY STOPKEY
224K
28M
64460 (1)
4
HASH UNIQUE
224K
28M
58849 (1)
5
FILTER
6
HASH JOIN OUTER
224K
28M
53237 (1)
7
NESTED LOOPS
8
NESTED LOOPS
347
29842
528 (0)
9
TABLE ACCESS BY INDEX ROWID
LB_T_XXXJECT_PROVIDER
347
21167
181 (0)
10
INDEX RANGE SCAN
IDX_PROJECT_PROVIDER_COMB1
182
4 (0)
11
INDEX UNIQUE SCAN
PK_LA_XXCKAGE
1
0 (0)
12
TABLE ACCESS BY INDEX ROWID
LA_XXCKAGE
1
25
1 (0)
13
VIEW
LB_T_XXXVIDER
9125K
409M
52700 (1)
14
HASH JOIN OUTER
9125K
556M
52700 (1)
15
TABLE ACCESS FULL
XXCC_SUPPLIER
26139
1148K
404 (0)
16
VIEW
6283K
113M
52287 (1)
17
SORT GROUP BY
6283K
185M
52287 (1)
18
TABLE ACCESS FULL
XXCC_SUPPLIER_CONTACT
10M
309M
148 (9)
cardinality feedback used for this statement
说明上面统计信息与实际数据存在非常大的差异，是引起执行计划错误的真正原因
2.4 错误执行计划与正确执行计划CPU资源消耗差异巨大对比
此处为选择一条最严重的SQL语句为例，其它语句比例相近
SQL ID: bj75p9188y410
#
Plan Hash Value
Total Elapsed Time(ms)
Executions
1st Capture Snap ID
Last Capture Snap ID
1
3990363694
4,585,425
9
33676
33677
2
6178145
2,838
2
33677
33677
3
2354817963
1,461
1
33677
33677
错误执行计划CPU消耗是最优执行计划CPU消耗的348倍
2.5 问题自动修复原因
ORACLE11G 的新功能cardinality feedback可以在上次运行完成后，得到上一次运行的基数真正结果，智能的调整后面语句运行时的执行计划，通过cardinality feedback功能得到准确基数数据后调整的执行计划，会给出下面提示：
cardinality feedback used for this statement
3、数据库时间与AWR快照对应信息
此在列出时间与AWR快照对应信息的原因为后续分析依赖时间与快照的关系，展示阶段性数据
序号
snap_id
BEGIN_INTERVAL_TIME
END_INTERVAL_TIME
1
33675
05-8月 -13 08.30.41.054
05-8月 -13 09.00.09.786
2
33676
05-8月 -13 09.00.09.786
05-8月 -13 09.30.10.502
3
33677
05-8月 -13 09.30.10.502
05-8月 -13 10.00.26.364
4
33678
05-8月 -13 10.00.26.364
05-8月 -13 10.30.18.791
5
33679
05-8月 -13 10.30.18.791
05-8月 -13 11.00.24.540
4、总体原因具体分析
8月5日9：00—10：00AWR报告分析
SQL ordered by CPU Time
NO
CPU Time (s)
Executions
CPU per Exec (s)
Elapsed Time (s)
%CPU
%IO
SQL Id
SQL Text
1
2,927.66
12
243.97
4,589.72
63.79
0.00
bj75p9188y410
select * from ( select distinc...
2
1,771.52
3,820
0.46
2,660.05
66.60
0.00
gwz243zx18jk0
SELECT * FROM PUB_STRU_TYPE_RE...
3
1,687.68
6
281.28
1,981.37
85.18
0.00
gmfktzfsd6hj3
select * from ( select row_.*,...
4
1,320.77
18
73.38
2,050.40
64.42
0.00
1d44jc4at7xt6
select count(0) from ( select ...
5
870.33
745
1.17
1,288.11
67.57
0.00
4x0jsx8xmrq3c
select count(1) rcount from ( ...
6
856.20
63
13.59
1,096.32
78.10
0.00
1ztsa8nc1arn1
SELECT DISTINCT RFX2.rootId F...
7
752.07
429
1.75
1,145.77
65.64
0.00
9rpn6kmf9vwwh
select p.package_id, p.package...
8
729.02
94
7.76
853.01
85.46
0.00
bq1x40gqtd1r3
SELECT DISTINCT RFX2.rootId F...
9
683.45
12
56.95
1,538.29
44.43
37.32
f760vj05hjpww
SELECT DISTINCT RFX1.rootId F...
10
595.38
2
297.69
632.09
94.19
0.00
fh86uz0ch9z9w
select count(0) from ( select ...
分析：
(1) 上述标红色语句共四条，其中第4条和第10条其实为同一条SQL语句
(2) 上述四条标红色SQL语句分析为最消耗CPU资源的语句
(3) 上述四条标红色SQL语句在出问题前都没有运行，基本都集中在9：00以后开始运行
(4) 上述标红色语句的问题有共同特性，都调用了LB_T_XXXVIDER视图、LB_T_XXXJECT_PROVIDER表、LA_XXCKAGE
(5) 上述标红色语句都是因为优化器对LB_T_XXXVIDER视图、LB_T_XXXJECT_PROVIDER表、LA_XXCKAGE表的基数数据评估发生了巨大的差错，导致选择了错误的执行计划，消耗大量的CPU资源，导致CPU接近100%
(6) 上述标红色语句都是在几次错误选择后有效的利用了ORACLE11g的新特性cardinalityfeedback功能，最终得到准确的基数数据，自行修正了执行计划
5、问题语句逐条剖析
5.1 第一条：SQL_ID：bj75p9188y410
SQL ID: bj75p9188y410
#
Plan Hash Value
Total Elapsed Time(ms)
Executions
1st Capture Snap ID
Last Capture Snap ID
1
3990363694
4,585,425
9
33676
33677
2
6178145
2,838
2
33677
33677
3
2354817963
1,461
1
33677
33677
分析：
(1)标红色的为错误的执行计划及其统计信息
(2)9：00—10：00之间，共发生9次错误的执行计划
(3)在前面发生9次错误的执行计划之后，由于ORACLE 11G的cardinality feedback新功能，最终得到准确的基数，在9：30-10：00之间，自动纠正了执行计划
5.2 第二条：SQL_ID：gmfktzfsd6hj3
SQL ID: gmfktzfsd6hj3
#
Plan Hash Value
Total Elapsed Time(ms)
Executions
1st Capture Snap ID
Last Capture Snap ID
1
617277444
2,602,874
6
33677
33678
2
2335536944
2,725
2
33678
33678
3
687995303
1,437
1
33678
33678
分析：
(1)标红色的为错误的执行计划及其统计信息
(2)9：30—10：30之间，共发生6次错误的执行计划
(3)在前面发生6次错误的执行计划之后，由于ORACLE 11G的cardinality feedback新功能，最终得到准确的基数，在10：00-10：30之间，自动纠正了执行计划
5.3 第三条：SQL_ID：1d44jc4at7xt6
SQL ID: 1d44jc4at7xt6
#
Plan Hash Value
Total Elapsed Time(ms)
Executions
1st Capture Snap ID
Last Capture Snap ID
1
3265929876
2,029,525
4
33676
33677
2
2949667951
19,116
13
33676
33677
3
1227972422
1,761
1
33676
33677
分析：
(1)标红色的为错误的执行计划及其统计信息
(2)9：00—10：00之间，共发生4次错误的执行计划，其中
(3)在前面发生4次错误的执行计划之后，由于ORACLE 11G的cardinality feedback新功能，最终得到准确的基数，在9：30-10：00之间，自动纠正了执行计划
5.4 第四条：SQL_ID：fh86uz0ch9z9w
SQL ID: fh86uz0ch9z9w
#
Plan Hash Value
Total Elapsed Time(ms)
Executions
1st Capture Snap ID
Last Capture Snap ID
1
3265929876
1,247,089
4
33676
33681
2
2949667951
2,624
2
33681
33681
3
1227972422
1,291
1
33681
33681
分析：
(1)标红色的为错误的执行计划及其统计信息
(2)9：00—11：30之间，共发生4次错误的执行计划，其中两次发生在9：00-9：30间
(3)在前面发生4次错误的执行计划之后，由于ORACLE 11G的cardinality feedback新功能，最终得到准确的基数，在11：00-11：30之间，自动纠正了执行计划
6、引发执行计划错误原因分析
6.1 表统计信息统计历史
6.1.1 LB_T_XXXJECT_PROVIDER
序号
用户名
表名
分析历史时间
1
BIDPRO
LB_T_XXXJECT_PROVIDER
11-8月 -13 20.06.16.630512
2
BIDPRO
LB_T_XXXJECT_PROVIDER
03-8月 -13 20.22.23.332654
3
BIDPRO
LB_T_XXXJECT_PROVIDER
26-7月 -13 22.18.08.386638
在8月5日开标前，该表已经有10天未统计
6.1.2 LA_XXCKAGE
序号
用户名
表名
分析历史时间
1
BIDPRO
LA_XXCKAGE
15-8月 -13 20.01.28.232128
2
BIDPRO
LA_XXCKAGE
09-8月 -13 20.04.35.224700
3
BIDPRO
LA_XXCKAGE
26-7月 -13 20.08.49.666682
在8月5日开标前，该表已经有10天未统计
6.1.3 XXCC_SUPPLIER
序号
用户名
表名
分析历史时间
1
BIDPRO
XXCC_SUPPLIER
18-8月 -13 20.13.21.031834
2
BIDPRO
XXCC_SUPPLIER
10-8月 -13 20.07.04.740643
3
BIDPRO
XXCC_SUPPLIER
31-7月 -13 22.00.39.107474
4
BIDPRO
XXCC_SUPPLIER
22-7月 -13 22.01.26.170018
在8月5日开标前，该表已经有5天未统计
6.1.4 XXCC_SUPPLIER_CONTACT
序号
用户名
表名
分析历史时间
1
BIDPRO
XXCC_SUPPLIER_CONTACT
17-8月 -13 20.03.30.834585
2
BIDPRO
XXCC_SUPPLIER_CONTACT
09-8月 -13 22.03.30.402420
3
BIDPRO
XXCC_SUPPLIER_CONTACT
26-7月 -13 22.07.06.696581
在8月5日开标前，该表已经有10天未统计
6.2 表数据变化分析
6.2.1 8月5日前最后一次统计时间至8月5日时的block_changes数量
序号
表名
最后一次统计时间
block_changes
1
LB_T_XXXJECT_PROVIDER
26-7月 -13 22.18
158560
2
LA_XXCKAGE
26-7月 -13 20.08
168224
3
XXCC_SUPPLIER
31-7月 -13 22.00
608
4
XXCC_SUPPLIER_CONTACT
26-7月 -13 22.07
576
6.3 错误执行计划预估数据量与真正数据量差异对比
SQL_ID
执行计划对错区分
对表的ROWS评估数
XXCC_SUPPLIER_CONTACT
XXCC_SUPPLIER
LA_XXCKAGE
LB_T_XXXJECT_PROVIDER
bj75p9188y410
错误执行计划
30058
1
1
1
正确执行计划
10M
26139
1
347
gmfktzfsd6hj3
错误执行计划
30058
1
1
1
正确执行计划
10M
26139
1
347
1d44jc4at7xt6
错误执行计划
30058
1
1
1
正确执行计划
10M
26139
1
347
fh86uz0ch9z9w
错误执行计划
30058
1
1
1
正确执行计划
7763K
26139
1
347
7、解决方案建议
建议对上述四条发生执行计划错误的SQL语句，采用SQL_PROFILE对执行计划进行固定，可以避免下次开标时出现同样的问题
本文原创发布php中文网，转载请注明出处，感谢您的尊重！
扫一扫
3917
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
