awr性能问题排查第一篇

对于awr，里面涵盖的内容比较杂，有时候看报告的时候总是不知道该怎么下手。时间长了，可能会有一些阅读习惯或者心得。今天在看大师chris lawson的一篇博文对于awr的一些心得( http://www.oraclemagician.com/white_papers/10awr.pdf )，还是蛮有收获，赶紧按照这个方子来细细品味一番。
首先是查看等待事件，这个也是老规矩。
不过先把db time先附上，更有针对性。
这是一个10分钟的awr报告，基于Linux平台，11gR2 64位。

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	17148	31-Oct-14 13:20:02	3397	5.6
End Snap:	17149	31-Oct-14 13:30:03	3471	5.7
Elapsed:		10.01 (mins)
DB Time:		262.49 (mins)

Top 5 Timed Foreground Events

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
db file sequential read	7,138,268	9,948	1	63.16	User I/O
DB CPU		4,405		27.97
direct path read	104,507	903	9	5.73	User I/O
db file parallel read	103,319	336	3	2.13	User I/O
log file sync	49,187	282	6	1.79	Commit

-->查看sequential read指标
这个指标很实用，可以在不同的平台间进行比较,但是scattered read这种指标就不好比较了。
延迟一般需要在10ms以下,或者至少100 reads/sec，在基于SAN存储缓存数据的情况下，sequential read的指标有时候会保持在2ms左右，这个只能说明SAN已经把数据转化为缓存了，倒不能说明硬盘驱动确实很快。
上面的awr可以看到平均的延迟是在1ms以内，算是正常。

-->查看top elapsed time sql
这个时候可以根据elapsed time得到一个sql执行情况的概览。查看这个的主要目的就是得到执行时间较长的sql语句。按照10分钟对的一个频度，executions为0的sql都需要格外注意，同时兼顾所占的比例。

SQL ordered by Elapsed Time

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
1,243.85	29	42.89	7.90	7.32	94.81	cjxrg4qpadvgw	fextract@ccbdbpr1 (TNS V1-V3)	SELECT .
942.47	27	34.91	5.98	7.81	95.75	5y3d011ygwfyx	fextract@ccbdbpr1 (TNS V1-V3)	SELECT
613.45	0		3.90	4.81	97.32	9yn2xdw7uy0bq	JDBC Thin Client	select /*+ index(s SERVICE_
606.64	555	1.09	3.85	94.74	4.89	7yp93zzstn5gh	TB1Manager@ccbdbpr1 (TNS V1-V3)	update (select /*+ index(
602.56	0		3.83	14.57	90.57	0cdthzpx2jn4q	JDBC Thin Client	SELECT
602.53	0		3.83	4.70	97.30	b4c5cvdza03m3	JDBC Thin Client	SELECT
578.66	31	18.67	3.67	11.61	92.22	cc9x1wp2tdgdx	fextract@ccbdbpr1 (TNS V1-V3)	SELECT
547.03	1	547.03	3.47	78.67	17.69	gbqz84d1jggdq	JDBC Thin Client	/* MMO_Memo_getMemoList_1 */ S...
523.83	3	174.61	3.33	29.21	72.21	4gz51fphuarsw	JDBC Thin Client	/*ProcInstScanner_selectAv...
496.38	0		3.15	4.73	96.39	6gvd0gbp58kbc	SQL*Plus	INSERT INTO ..
420.94	6	70.16	2.67	48.53	49.96	00jrngwmz2vxx	JDBC Thin Client	select...

标黄的部分就是参考的依据，可以根据elapsed time和executions来做一个评估。

-->查看db time
这个部分可以根据time model的部分得到。这个部分能够得到一个大体的比例，看看db time都主要耗在哪些方面了。

Statistic Name	Time (s)	% of DB Time
sql execute elapsed time	14,854.47	94.32
DB CPU	4,404.99	27.97
parse time elapsed	64.23	0.41
PL/SQL execution elapsed time	36.26	0.23
sequence load elapsed time	24.11	0.15
hard parse elapsed time	8.79	0.06
connection management call elapsed time	7.85	0.05
RMAN cpu time (backup/restore)	7.74	0.05
inbound PL/SQL rpc elapsed time	6.28	0.04
repeated bind elapsed time	0.11	0.00
hard parse (sharing criteria) elapsed time	0.06	0.00
failed parse elapsed time	0.03	0.00
PL/SQL compilation elapsed time	0.01	0.00
DB time	15,749.31
background elapsed time	1,394.65
background cpu time	68.34

-->查看硬盘读的消耗部分
通过这个部分可以得到哪些sql正在进行大量的硬盘读，通过sql order by reads来得到。
经过分析
sql(gbqz84d1jggdq )占用了22%的硬盘读，比例是很高的，查看sql语句发现走的是一个全表扫描，表是亿级的大表。
sql( 00jrngwmz2vxx)使用union的地方存在问题，导致了全表扫描，细节可以参考http://blog.itpub.net/23718752/viewspace-1209397/  已经做了完整的调优解释。
sql( 4gz51fphuarsw, 6fu3z8pqd2y9g)是产品线的两个通用sql,已经做了优化，其中有个大表做了全表扫描加并行，相对了最快的方式了。
sql( 98dyqu3xsgyf5)是一个简单的select 查询，但是也走了全表扫描，经过排查发现这个大表竟然在最开始规划的时候丢掉了索引，所以这个问题也是一个比较纠结的错误。需要协调解决。

Physical Reads	Executions	Reads per Exec	%Total	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
8,901,984	1	8,901,984.00	22.37	547.03	78.67	17.69	gbqz84d1jggdq	JDBC Thin Client	/* MMO_Memo_getMemoList_1 */ S...
6,712,998	6	1,118,833.00	16.87	420.94	48.53	49.96	00jrngwmz2vxx	JDBC Thin Client	/* AR9_AR9GetPaymentSMS_select...
5,957,336	3	1,985,778.67	14.97	523.83	29.21	72.21	4gz51fphuarsw	JDBC Thin Client	/* CL_ProcInstScanner_selectAv...
4,880,228	3	1,626,742.67	12.26	309.94	18.47	78.67	6fu3z8pqd2y9g	JDBC Thin Client	/* CL_WaitScanner_selectWorkab...
2,015,674	36	55,990.94	5.06	94.81	27.40	70.35	98dyqu3xsgyf5	JDBC Thin Client	/* null_CL9CrdMntrExtract_sele...

-->查看logical reads
这个部分可以排查出那些执行效率低下的sql语句。
查看以下的几个sql,
sql( 7yp93zzstn5gh)消耗了大量的逻辑读,经过查看，这个sql语句没有问题，但是表级存在着大量的碎片，一个分区表只有几十条数据，但是blocks却有几十万。
sql( 1hg2wcuapy3y3)查看执行计划时，发现执行计划的消耗太高。cost达到近 273K,这条sql语句还是需要好好排查一番。

Buffer Gets	Executions	Gets per Exec	%Total	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
509,827,210	555	918,607.59	61.98	606.64	94.74	4.89	7yp93zzstn5gh	B1Manager@ccbdbpr1 (TNS V1-V3)	update (select /*+ index(B1_...
30,887,996	14	2,206,285.43	3.76	25.51	99.95	0.04	1hg2wcuapy3y3	JDBC Thin Client	select un_request.run_mod...

-->查看commit频率
这个部分可以查看是否日志切换较为频繁，或者在进行着大量的事物处理，可以看看用户进行commit的频度

Instance Activity Stats

Statistic	Total	per Second	per Trans
user calls	7,073,740	11,777.75	216.38
user commits	32,485	54.09	0.99
user rollbacks	207	0.34	0.01

-->查看系统负载
这个部分可以查看系统级的一些指标，如果时间较长，就有多行的数据可以参考。总体来看iowait的比例不高。

Operating System Statistics - Detail

Snap Time	Load	%busy	%user	%sys	%idle	%iowait
31-Oct 13:20:02	38.14
31-Oct 13:30:03	39.55	21.82	17.03	3.41	78.18	0.19

-->查看热对象
可以通过segments by logical reads来得到一些比较热的对象，可能是表，或者索引。
如果比例很高，可以通过这些热对象从sql列表中排查一下，到底是哪些sql语句和这个热对象相关。可能sql语句单独执行很快，多个并发的进程时速度就会受到影响了。

Owner	Tablespace Name	Object Name	Subobject Name	Obj. Type	Logical Reads	%Total
APPO	INDXS01	CYCLE_GROUPS_PK		INDEX	41,559,296	5.05
EFWORK	DATAL01	OFFER		TABLE	20,566,400	2.50
APPO	DATAS01	STEP_INST		TABLE	10,610,368	1.29

-->查看物理读最高的对象
这个部分可以通过如下的方式查询。排查表 FILES_CONTROL的时候，发现sql列表中的一个对应的sql语句走了全表扫描，这个表本来数据量就有好几百万，走全表扫描还是可以完全避免的。

Segments by Physical Reads

Owner	Tablespace Name	Object Name	Subobject Name	Obj. Type	Physical Reads	%Total
APPO	DATAS01	STEP_INST		TABLE	10,101,327	25.38
APPO	DATAS01	FILES_CONTROL		TABLE	2,042,467	5.13
APPO	DATAS01	ACCOUNT		TABLE	920,202	2.31
APPO	DATAM01	DOCUMENT	P120_C10	TABLE PARTITION	905,729	2.28