一般来说一条sql语句执行个4秒钟是可以接受的，没有什么问题，但是如果应该执行1秒，却执行了4秒，问题就挺大的了。
今天查看数据库负载，发现在中午12:00 到1点之间，数据库的负载急剧增加，负载达到了百倍。

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	15106	29-Sep-14 12:00:07	1602	7.3
End Snap:	15107	29-Sep-14 13:00:13	2807	9.7
Elapsed:		60.10 (mins)
DB Time:		8,575.93 (mins)

为了一看究竟，抓取了一个awr报告。
发现系统的负载情况确实很严重，每秒的redo有1.6M,可见系统的负载不是主要在select上，可能有一些dml之类的操作极为频繁。

	Per Second	Per Transaction	Per Exec	Per Call
DB Time(s):	142.7	1.7	0.04	0.03
DB CPU(s):	5.9	0.1	0.00	0.00
Redo size:	1,694,755.6	20,724.1
Logical reads:	671,861.2	8,215.8
Block changes:	6,638.8	81.2
Physical reads:	51,477.6	629.5
Physical writes:	1,075.6	13.2
User calls:	5,458.5	66.8
Parses:	1,247.7	15.3
Hard parses:	2.0	0.0
W/A MB processed:	34.3	0.4
Logons:	1.9	0.0
Executes:	3,522.4	43.1
Rollbacks:	0.5	0.0
Transactions:	81.8

看了下等待事件。都是关于lock的。这个时候就有些纳闷了。到底什么样的操作会导致严重的锁等待。

Top 5 Timed Foreground Events

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
enq: TX - row lock contention	1,132,995	235,312	208	45.73	Application
log file sync	305,880	120,935	395	23.50	Commit
db file sequential read	35,361,005	110,402	3	21.46	User I/O
DB CPU		21,248		4.13
read by other session	259,224	17,942	69	3.49	User I/O

首先DB time极高，这个时候就可以关注一些elapsed time比较高的sql语句。
可以看到第一个sql语句占用了大量的时间，而且是一个dml语句。后面的几个都是select相关的，占用的比例不是很大，就没有全列出来。

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
235,032.84	57,646	4.08	45.68	0.06	0.00	cws3pma51s3tf	JDBC Thin Client	update EC1_USER set SYS_UPDAT...
14,459.33	0		2.81	30.97	70.80		ORACLE.EXE	SELECT "A3"."SUBSCRIBER_NO", "...
11,493.79	375,757	0.03	2.23	0.88	99.41	bhm5y9tb096qd	JDBC Thin Client	selectNameAd...

这个时候怎么把这条sql语句和对应的等待时间关联起来呢，如果为了清晰方便，可以使用ash。
Top SQL with Top Events

SQL ID	Planhash	Sampled # of Executions	% Activity	Event	% Event	Top Row Source	% RwSrc	SQL Text
cws3pma51s3tf	3040658791	5229	55.84	enq: TX - row lock contention	55.82	UPDATE	55.82	update EC1_USER set SYS_UPDAT...
bhm5y9tb096qd	1654978926	324	2.32	db file sequential read	1.62	INDEX - RANGE SCAN	0.48	selectNameAd...
	418872265	4	2.30	db file sequential read	1.58	TABLE ACCESS - FULL	1.10	SELECT "A3"."SUBSCRIBER_NO", "...
	799822736	160	1.35	read by other session	0.82	INDEX - UNIQUE SCAN	0.46	selectS...

问题基本确定了，是这条Update语句的执行极为频繁，但是执行时间达到了4秒。一个小时以内执行了5万多次。
但是为什么sql语句的执行时间这么长呢，是不是没有走索引，在简单排查了一下，索引是启用了的。
抓了一个awrsqrpt的报告。可以看到执行计划中的唯一性索引是启用了的，而且查取效率很多。0.01秒就查到了对应的记录，对于update的部分，不会那么慢把。

Execution Plan

Id	Operation	Name	Rows	Bytes	Cost (%CPU)	Time
0	UPDATE STATEMENT				1 (100)
1	UPDATE	EC1_USER
2	INDEX UNIQUE SCAN	EC1_USER_PK	1	102	1 (0)	00:00:01

这个时候怎么解释执行计划效率很高，但是执行时间却很长的问题。
第一个猜想就是系统的负载加大了，可能查取数据的时候就慢了。但是反过来说，也不会慢这么高的比例啊。
所以这种猜想不成立的。
第二个猜想就是有大量的并发dml,同时做update,导致其他的一些Update就在等待。当然这种设计是有问题的。
但是时间已经过去了很久，v$session里面早就没有对应的记录了。怎么验证自己的猜想呢。
还是使用ash。里面有一个章节是blocking sessions的细节。

Blocking Sid (Inst)	% Activity	Event Caused	% Event	User	Program	# Samples Active	XIDs
2647, 1( 1)	16.74	log file sync	16.74	SYS	oracle@xxxx(LGWR)	97/360 [ 27%]	0
2909,15473( 1)	3.77	enq: TX - row lock contention	3.77	ECC	JDBC Thin Client	45/360 [ 13%]	0
3624,52345( 1)	3.01	enq: TX - row lock contention	3.01	ECC	JDBC Thin Client	44/360 [ 12%]	1
6453,29237( 1)	2.83	enq: TX - row lock contention	2.83	ECC	JDBC Thin Client	18/360 [ 5%]	0
793,65345( 1)	2.79	enq: TX - row lock contention	2.79	ECC	JDBC Thin Client	65/360 [ 18%]	0

通过这个就能看到有4个并发的session在同时做dml操作了。这样问题就能够基本定位了。
有了这些信息，就可以和开发部门协调。看看下一步该怎么改进了。

文章来源：

ITPub博客

一条执行4秒的sql语句导致的系统问题

最新文章