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

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

2024-08-07 22:53:39   218人阅读

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




本文作者：黎俊杰（网名：踩点），从事”系统架构、操作系统、存储设备、数据库、中间件、应用程序“六个层面系统性的性能优化工作

欢迎加入系统性能优化专业群，共同探讨性能优化技术。群号：258187244


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


联系
我们