AWR报告分析之一：高 DB CPU 消耗的性能根源

原创 eygle 2012-11-22

1306

准备写一个系列，跟进一些AWR报告，做一些简单分析，从中表达一些思路和想法，这些AWR报告可能来自公众发布，在这里予以引用。

以下这份AWR报告的TOP 5 Event可以看出，其CPU消耗超高，占 42.59% 的事件比例，而Log File Sync单次等待达到12毫秒，这表明IO可能存在迟缓：

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
DB CPU		22,574		42.59
log file sync	25,313	310	12	0.58	Commit
db file sequential read	10,645	24	2	0.05	User I/O
direct path read	9,191	22	2	0.04	User I/O
enq: TX - row lock contention	11	5	455	0.01	Application

这个报告来自60分钟的数据库采样：

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	6603	19-Nov-12 08:00:15	261	2.2
End Snap:	6604	19-Nov-12 09:00:20	260	3.0
Elapsed:		60.09 (mins)
DB Time:		883.34 (mins)

关注一下负载概要信息，数据库每秒仅仅折合4.8个事务，而此前的LOG File Sync等待较高，这说明IO资源可能被其他操作占用，事务之外，就是查询，也就是说，可能有大量低效查询消耗尽了IO资源：

	Per Second	Per Transaction	Per Exec	Per Call
DB Time(s):	14.7	3.0	0.07	0.02
DB CPU(s):	6.3	1.3	0.03	0.01
Redo size:	55,291.8	11,421.6
Logical reads:	662,383.2	136,828.5
Block changes:	189.9	39.2
Physical reads:	7.0	1.5
Physical writes:	19.9	4.1
User calls:	883.5	182.5
Parses:	21.1	4.4
Hard parses:	3.4	0.7
W/A MB processed:	1,170.6	241.8
Logons:	1.2	0.3
Executes:	214.9	44.4
Rollbacks:	0.0	0.0
Transactions:	4.8

通过SQL的SQL逻辑读部分，可以发现导致异常的SQL查询，前两个SQL供占72.27的逻辑读，显然是这两条SQL消耗了IO资源：

Buffer Gets	Executions	Gets per Exec	%Total	Elapsed Time (s)	%CPU	SQL Id	SQL Module	SQL Text
1,171,388,996	90,764	12,905.88	49.05	30,514.20	44.7	08v35uwaj38aa	JDBC Thin Client	select * from ( select row_.*,...
554,429,813	42,299	13,107.40	23.22	9,923.23	40.9	btn84j9rhuf4h	JDBC Thin Client	select * from ( select row_.*,...
503,809,511	127,506	3,951.26	21.10	7,669.52	37.3	cp9wdanzmzj4q	JDBC Thin Client	select * from (select JOBID, S...
30,497,069	2,331	13,083.26	1.28	409.63	42.2	fqjyuzjgm89qv	JDBC Thin Client	select * from ( select trunc(P...
24,457,802	1,607	15,219.54	1.02	208.90	45.4	8tptxzh309raz	JDBC Thin Client	select this_.PID as PID10_0_, ...
10,935,241	3,791	2,884.53	0.46	462.83	40.4	9dpwkhfwnqfqa	JDBC Thin Client	select * from (select JOBID, S...
8,294,720	799	10,381.38	0.35	73.10	40.1	0nn3rt489dkqz	JDBC Thin Client	select * from ( select row_.*,...
8,090,724	581	13,925.51	0.34	209.79	43.3	5902s014jdg6n	JDBC Thin Client	select * from ( select trunc(P...
4,568,220	123	37,140.00	0.19	19.83	37.9	55u237k35a317	JDBC Thin Client	select * from ( select rownum ...
4,151,731	316	13,138.39	0.17	28.95	37.8	d1515xp5t2xtw	JDBC Thin Client	select * from (select JOBID, S...

在"Segments by Logical Reads"部分可以看到，逻辑读集中在一个对象上，第一位的表分区占用89.86%的逻辑读：

Owner	Tablespace Name	Object Name	Subobject Name	Obj. Type	Logical Reads	%Total
NCSS	NCSSJOBSITE00	STU_SEARCHJOB	SITE00	TABLE PARTITION	2,145,895,024	89.86
STPSUSER	STPS2	TEACHER_INFO		TABLE	35,438,144	1.48
NCSS	NCSS_INDEX	STU_SEARCHJOB_PK		INDEX	18,438,384	0.77
NCSS	NCSSJOBSITE0000	STU_SEARCHJOB	SITE2101	TABLE PARTITION	17,049,488	0.71
NCSS	NCSS	STU_BASICINFO		TABLE	5,766,448	0.24

接下来如果考察SQL，观察其执行计划，就应该能够发现，可能是索引缺失导致了全表或全分区的扫描。

AWR报告参考链接：

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者