一条简单的sql语句导致的系统问题-白红宇

一条简单的sql语句导致的系统问题

阅读量：2447 次

发布时间：2019-05-10

本文共 4655 字，大约阅读时间需要 15 分钟。

新年，给大家拜年了。祝大家工作顺利，万事如意。

今天照例简单检查了系统的情况，发现在客户的服务器在下午的3-5点这个时间段，数据库负载略有上升，但是幅度不大，因为生产的awr抓取频率是10分钟，所以还是能够通过awr分析出一些问题。

负载情况如下：

抓取了一个最新时间段的awr报告。

查看数据库负载，比平时的负载要高一些。

Host Name	Platform	CPUs	Cores	Sockets	Memory (GB)
xxxxx	Linux x86 64-bit	80	40	4	346.22

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	33108	19-Feb-15 15:40:21	5147	5.4
End Snap:	33109	19-Feb-15 15:50:22	5256	5.5
Elapsed:		10.01 (mins)
DB Time:		533.14 (mins)

从这个概览来看还是看不出特别之处，只能对整体的情况有一个把握。这是一个10分钟的报告。

Load profile是我查看awr报告的重点部分。能够发现user calls和executions的值很高。

Load Profile

	Per Second	Per Transaction	Per Exec	Per Call
DB Time(s):	53.3	0.9	0.00	0.00
DB CPU(s):	10.3	0.2	0.00	0.00
Redo size:	2.2 MB	37.4 KB
Logical reads:	10.3 GB	179.3 MB
Block changes:	10,738.9	182.2
Physical reads:	1.2 GB	21.5 MB
Physical writes:	7.8 MB	136.0 KB
User calls:	20,256.8	343.7
Parses:	2,447.3	41.5
Hard parses:	4.3	0.1
W/A MB processed:	72.5	1.2
Logons:	4.6	0.1
Executes:	11,414.1	193.7
Rollbacks:	0.6	0.0
Transactions:	58.9

这个时候基本能够从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

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
db file sequential read	13,019,569	15,375	1	48.06	User I/O
enq: TX - row lock contention	403	7,779	19303	24.32	Application
DB CPU		6,185		19.34
direct path read	425,941	1,882	4	5.88	User I/O
read by other session	1,126,812	774	1	2.42	User I/O

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

但是这个问题和load profile中的user calls,executions的值过高应该没有太大的关系。我们来直接进入sql信息部分。

SQL ordered by Elapsed Time

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Module	SQL Text
01:39:59	1,344	4.46	18.75	0.33	0.00	JDBC Thin Client	/* CL_ProcessController_update...
01:25:38	95	54.08	16.06	6.94	96.79	bl1extract@ccbdbpr1 (TNS V1-V3)	SELECT /*+ leading (list payp...
2,612.67	206	12.68	8.17	8.55	94.69	bl1extract@ccbdbpr1 (TNS V1-V3)	SELECT /*+ leading (cust rate ...
1,800.85	519	3.47	5.63	0.01	0.00	JDBC Thin Client	/* AC_AcCloseUpdateAcControl_u...
1,554.22	13	119.56	4.86	17.15	86.22	JDBC Thin Client	select /*+ leading (bpm_ai bpm...
1,476.63	13	113.59	4.62	30.53	66.68	JDBC Thin Client	/* CL_ProcInstScanner_selectAv...
952.12	361,344	0.00	2.98	12.69	92.74	bl1extract@ccbdbpr1 (TNS V1-V3)	/* */ SELECT CUSTOMER_ID, SUBS...
924.90	13	71.15	2.89	30.09	66.53	JDBC Thin Client	/* CL_WaitScanner_selectWorkab...
600.66	0		1.88	8.85	94.53	JDBC Thin Client	SELECT OK.BAN, OK.MSISDN, OK.P...
565.49	0		1.77	4.19	97.80	JDBC Thin Client	/* Formatted on 2012/04/26 16:...
514.37	2,552,072	0.00	1.61	99.27	0.00	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 Module	SQL Text
1.2 TB	2,552,072	486.9 KB	19.12	514.37	99.27	0.00	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	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	JDBC Thin Client	/* CL_ProcInstScanner_selectAv...
228.4 GB	13	17.6 GB	3.69	924.90	30.09	66.53	JDBC Thin Client	/* CL_WaitScanner_selectWorkab...
190.4 GB	335	582.0 MB	3.07	192.38	99.90	0.00	JDBC Thin Client	SELECT COUNT(1) FROM (/* null_...

SQL ordered by Executions

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

这个时候通过这三个部分，能够基本定位出问题发生在sql_id 这个语句上，这个语句就是一个简单的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，确实让我感觉很意外。

分析了这些问题之后，我的判断是认为程序逻辑中的问题，稍后发送了邮件和开发做确认。

通过这个问题可以看到sql语句导致的问题不一定是差的执行计划导致的，简单的sql语句照样能够导致一些意外的情况。但是执行的频率为什么这么频繁，还是属于应用部分，只能让他们提供更多的信息了。而且分析问题的时候，发现了一些问题，可能在检查的过程中又被其它的问题干扰了，很可能会让自己偏离问题检查的方向，很容易造成一个情况，发现忙活了半天，查问题的针对性不够。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/23718752/viewspace-1438776/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/23718752/viewspace-1438776/

你可能感兴趣的文章