首页    技术博客    PHP教程    数据库技术    前端开发   HTML5    Nginx    php论坛
新用户注册 | 会员登录
加入会员，解锁专属内容
取消
热门标签 | HotTags
当前位置:  开发笔记 > 数据库 > 正文

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

作者：Hancl | 来源：互联网 | 2018-06-08 11:32
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：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对执行计划进行固定，可以避免下次开标时出现同样的问题


推荐阅读
author-avatar
Hancl
这个家伙很懒，什么也没留下！
Tags | 热门标签
RankList | 热门文章
PHP1.CN | 中国最专业的PHP中文社区 | DevBox开发工具箱 | json解析格式化 |PHP资讯 | PHP教程 | 数据库技术 | 服务器技术 | 前端开发技术 | PHP框架 | 开发工具 | 在线工具
Copyright © 1998 - 2020 PHP1.CN. All Rights Reserved | 京公网安备 11010802041100号 | 京ICP备19059560号-4 | PHP1.CN 第一PHP社区 版权所有