新年，给大家拜年了。祝大家工作顺利，万事如意。今天照例简单检查了系统的情况，发现在客户的服务器在下午的3-5点这个时间段，数据库负载略有上升，但是幅度不大，因为生产的awr抓取频率是10分钟，所以还是能够通过awr分析出一些问题。负载情况如下：抓取了一个最新时间段的awr报告。查看数据库负载，比平时的负载要高一些。

从这个概览来看还是看不出特别之处，只能对整体的情况有一个把握。这是一个10分钟的报告。Load profile是我查看awr报告的重点部分。能够发现user calls和executions的值很高。

Load Profile

Convert to CSV

这个时候基本能够从load profile里面找到问题的方向了，user calls和executions的部分需要注意，首先问题的方向很可能是从sql语句级别导致的，语句执行的如此频繁，势必会对buffer gets有较大的影响，这个报告中parses的值很低，至少说明问题不是由于绑定变量导致的。我们可以查看等待事件基本确定时间都去哪了，哪些等待事件是需要重点关注的。然后在sql语句部分来分析了，基本可以从order by Elapsed time, order by Gets, order by Executions这三个部分来佐证了。等待事件如下：

Top 5 Timed Foreground Events

从这个等待事件可以看出，大部分的等待事件都集中在IO部分，当然导致的原因也是多方面的。第2个等待事件至少可以说明表中存在着锁，这个也可能是导致数据库负载增加的一个原因，在通过监控记录查看，或者抓取一个ash报告就能够基本定位出那个时间段的锁细节。已经做了确认，发现某一个process存在很多的并发dml操作，抓取了相应的信息交给了开发处理。

SQL ordered by Elapsed Time

• Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
  01:39:59	1,344	4.46	18.75	0.33	0.00	dch8sxwt6ujvc	JDBC Thin Client	/* CL_ProcessController_update...
  01:25:38	95	54.08	16.06	6.94	96.79	6csnjz5kqcffm	bl1extract@ccbdbpr1 (TNS V1-V3)	SELECT /*+ leading (list payp...
  2,612.67	206	12.68	8.17	8.55	94.69	ffnjuh9qz1wy8	bl1extract@ccbdbpr1 (TNS V1-V3)	SELECT /*+ leading (cust rate ...
  1,800.85	519	3.47	5.63	0.01	0.00	ffv3am85ccm25	JDBC Thin Client	/* AC_AcCloseUpdateAcControl_u...
  1,554.22	13	119.56	4.86	17.15	86.22	fg5mc598u799u	JDBC Thin Client	select /*+ leading (bpm_ai bpm...
  1,476.63	13	113.59	4.62	30.53	66.68	4gz51fphuarsw	JDBC Thin Client	/* CL_ProcInstScanner_selectAv...
  952.12	361,344	0.00	2.98	12.69	92.74	62h1u7vsgjx9p	bl1extract@ccbdbpr1 (TNS V1-V3)	/* */ SELECT CUSTOMER_ID, SUBS...
  924.90	13	71.15	2.89	30.09	66.53	6fu3z8pqd2y9g	JDBC Thin Client	/* CL_WaitScanner_selectWorkab...
  600.66	0		1.88	8.85	94.53	1taqbbq0mw35u	JDBC Thin Client	SELECT OK.BAN, OK.MSISDN, OK.P...
  565.49	0		1.77	4.19	97.80	cqrms45fqwvr3	JDBC Thin Client	/* Formatted on 2012/04/26 16:...
  514.37	2,552,072	0.00	1.61	99.27	0.00	0mynq29fmat7d	getdate_int@ccbdbpr1 (TNS V1-V3)	select TO_CHAR(LOGICAL_DATE, '...

SQL ordered by Gets

• Buffer Gets	Executions	Gets per Exec	%Total	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
  1.2 TB	2,552,072	486.9 KB	19.12	514.37	99.27	0.00	0mynq29fmat7d	getdate_int@ccbdbpr1 (TNS V1-V3)	select TO_CHAR(LOGICAL_DATE, '...
  705.8 GB	25	28.2 GB	11.39	105.95	72.71	27.95	1hg2wcuapy3y3	JDBC Thin Client	select bl1_run_request.run_mod...
  234.0 GB	13	18.0 GB	3.78	1,476.63	30.53	66.68	4gz51fphuarsw	JDBC Thin Client	/* CL_ProcInstScanner_selectAv...
  228.4 GB	13	17.6 GB	3.69	924.90	30.09	66.53	6fu3z8pqd2y9g	JDBC Thin Client	/* CL_WaitScanner_selectWorkab...
  190.4 GB	335	582.0 MB	3.07	192.38	99.90	0.00	aty7a3bvqfxxx	JDBC Thin Client	SELECT COUNT(1) FROM (/* null_...

SQL ordered by Executions

• Executions	Rows Processed	Rows per Exec	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
  2,552,072	2,551,077	1.00	514.37	99.27	0.00	0mynq29fmat7d	getdate_int@ccbdbpr1 (TNS V1-V3)	select TO_CHAR(LOGICAL_DATE, '...
  445,868	445,865	1.00	14.05	90.20	0.20	fa311gg43yjyf	JDBC Thin Client	Select CSM_TRX_1SQ.NEXTVAL fro...
  380,095	380,041	1.00	101.08	21.71	83.42	aprfnw5vk6szs	java_q4p@ccbappr7 (TNS V1-V3)	SELECT ch_objects.obj_id, ch_o...

这个时候通过这三个部分，能够基本定位出问题发生在sql_id 0mynq29fmat7d这个语句上，这个语句就是 一个简单的select查询，查询的表也很小。但是问题就是在10分钟的时间范围内执行了2百多万次，这确实很不正常。从sql order by elapased部分可以看出这个语句占用的 db time比例不高，从sql语句的执行上还是没有问题的，但是通过sql order by gets和execution这两个部分，可以很明显的看到，这条语句是top 1的语句，使用的buffer gets高达1T，这个表中的数据量就几千条数据，大小都是MB级别的，但是在10分钟内却能使用1T的buffer gets，确实让我感觉很意外。