您好,欢迎访问一九零五行业门户网

数据库服务器CPU突然持续100%后自动下降原因诊断

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对执行计划进行固定,可以避免下次开标时出现同样的问题
其它类似信息

推荐信息