一條執行4秒的sql語句導致的系統問題

一般來說一條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	7wx3cgjqsmnn4	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...
7wx3cgjqsmnn4	418872265	4	2.30	db file sequential read	1.58	TABLE ACCESS - FULL	1.10	SELECT "A3"."SUBSCRIBER_NO", "...
c0m89v4d91uhh	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操作了。這樣問題就能夠基本定位了。
有了這些資訊，就可以和開發部門協調。看看下一步該怎麼改進了。