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

原创: 2016-06-07 16:12:22 2649浏览

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评估数
SQL_ID	执行计划对错区分	XXCC_SUPPLIER_CONTACT	XXCC_SUPPLIER	LA_XXCKAGE	LB_T_XXXJECT_PROVIDER
bj75p9188y410	错误执行计划	30058	1	1	1
bj75p9188y410	正确执行计划	10M	26139	1	347
gmfktzfsd6hj3	错误执行计划	30058	1	1	1
gmfktzfsd6hj3	正确执行计划	10M	26139	1	347
1d44jc4at7xt6	错误执行计划	30058	1	1	1
1d44jc4at7xt6	正确执行计划	10M	26139	1	347
fh86uz0ch9z9w	错误执行计划	30058	1	1	1
fh86uz0ch9z9w	正确执行计划	7763K	26139	1	347