今天生產系統中的一個daemon出現了嚴重的資料處理延遲，客戶需要我們立即給出處理的方案。在綜合評估之後，為了不保證線上業務延遲，開發部門給出了臨時的解決意見。先停掉了一個應用，然後重啟之後那個daemon就沒有問題了。
等我連上系統，這個問題已經不存在了，但是還是要提供一些更加詳細的資訊來進一步診斷這個問題。
首先來明確問題，這個daemon出現的資料處理延遲，很可能是鎖造成的，從開發部門提供的臨時解決方向也是如此。從他們的排查來看，表PUB_LOG中可能存在著鎖等待。

因為時間已經過去一會了，使用awr報告檢視等待事件。看到了很明顯的row lock contention.

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
db file sequential read	7,686,909	10,052	1	44.39	User I/O
enq: TX - row lock contention	163	5,940	36442	26.23	Application

這個時候如果要進一步診斷這個等待事件，最好的工具就是ash了。
我們使用ash來檢視對應的等待事件，然後可以從報告中得知blocking session的資訊。這個可以和我們已經掌握的資訊來互相印證。

Blocking Sid (Inst)	% Activity	Event Caused	% Event	User	Program	# Samples Active	XIDs
7485,35335( 1)	25.79	enq: TX - row lock contention	25.79	PRODUSER	JDBC Thin Client	2/60 [ 3%]	1

在問題發生的時間段內的active session情況如下。

Sid, Serial#	% Activity	Event	% Event	User	Program	# Samples Active	XIDs
79,513,047	2.61	db file sequential read	2.08	CCBSFMDEV	plsqldev.exe	47/60 [ 78%]	1
117,218,815	2.61	CPU + Wait for CPU	2.34	PRDAPPC	JDBC Thin Client	53/60 [ 88%]	0
2430, 8909	2.61	db file sequential read	2.39	PRDAPPC	JDBC Thin Client	54/60 [ 90%]	0

這個時候我們已經得知了session的資訊。這個時候我們可以嘗試使用指令碼來檢視一下鎖的情況，如果對應的session還存在，我們可以基本定位客戶端的資訊了。
因為v$lock的資訊也是實時變化的，在生產中我們也是採用了一定的時間頻率來採集v$lock的資料。這些資訊透過awr,ash也是不能完全定位的，額外的工具補充對於排查問題就顯得尤為重要的。
以下是從監控存檔中得到了關於session(7485,35335)的鎖資訊。

SID_SERIAL ORACLE_USERN OBJECT_NAME LOGON_TIM SEC_WAIT OSUSER MACHINE PROGRAM STATE STATUS LOCK_ MODE_HELD
------------ ------------ ------------------------- --------- --------- ---------- ------------ -------------------- ---------- ---------- ----- ----------
7485,35335 PRODUSER PUB_LOG 09-DEC-14 18 mwrk01 fromClient1 JDBC Thin Client WAITING INACTIVE DML Row-X (SX)
7485,35335 PRODUSER ACCOUNT 09-DEC-14 18 mwrk01 fromClient2 JDBC Thin Client WAITING INACTIVE DML Row-X (SX)
7485,35335 PRODUSER CUSTOMER 09-DEC-14 20 lwrk01 fromClient2 sqlplus@ccbdbpr1 (TNS V1-V3) WAITING ACTIVE DML Row-X (SX)
7485,35335 PRODUSER PUB_LOG 09-DEC-14 18 mwrk01 fromClient2 JDBC Thin Client WAITING INACTIVE DML Row-X (SX)
7485,35335 PRODUSER SUBSCRIBER 09-DEC-14 18 mwrk01 fromClient2 JDBC Thin Client WAITING INACTIVE TO Row-X (SX)
7485,35335 PRODUSER ACCOUNT 09-DEC-14 18 mwrk01 fromClient2 JDBC Thin Client WAITING INACTIVE DML Row-X (SX)
7485,35335 PRODUSER SUBSCRIBER 09-DEC-14 18 mwrk01 fromClient2 JDBC Thin Client WAITING INACTIVE TO Row-X (SX)

有了這些資訊，我們就可以很確定的是在那個時間點上存在著表PUB_LOG相關的鎖。
但是光是確定了鎖，問題又回到原點了，這個問題是怎麼導致的呢。我們現在只是證明了這個問題是鎖引起的。
還需要更多的資訊來確定倒底是由哪些原因導致的。
這個時候還是需要透過awr來進一步來確定。
我們來看看資料庫的負載情況。相比於10分鐘的時間間隔來說，負載算是比較高的了。

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	22746	09-Dec-14 10:20:29	4510	6.0
End Snap:	22747	09-Dec-14 10:30:30	4523	5.9
Elapsed:		10.02 (mins)
DB Time:		377.45 (mins)

我們檢視load profile的資訊,可以很明顯的看到executes和logical reads的值很高。尤其是executes部分，系統看起來應該很忙啊，但是“DB CPU(s)”的值不高。可見cpu的利用率也不高。很可能是由於IO問題導致的。
聯絡logical_reads和physical reads，相比於physical writes，資料庫的負載基本都在於查詢。從這個角度來說，和executes的值又是有關聯的。

	Per Second	Per Transaction	Per Exec	Per Call
DB Time(s):	37.7	1.5	0.01	0.01
DB CPU(s):	8.8	0.3	0.00	0.00
Redo size:	836,276.6	32,374.8
Logical reads:	1,686,403.9	65,285.8
Block changes:	3,940.3	152.5
Physical reads:	57,841.1	2,239.2
Physical writes:	443.4	17.2
User calls:	5,872.6	227.4
Parses:	2,098.2	81.2
Hard parses:	3.5	0.1
W/A MB processed:	40.0	1.6
Logons:	3.1	0.1
Executes:	3,248.3	125.8
Rollbacks:	0.7	0.0
Transactions:	25.8

我們來看看在問題發生的時間段，到底是哪些查詢來執行，執行得這麼頻繁。
我們檢視SQL ordered by Elapsed Time 這個章節，可以得到資料庫負載的一個整體情況，看看是哪些sql語句的執行導致了整體的資料庫負載.
結果抓取到的第1條語句就是一個update，是在ACCOUNT上的update,執行頻率也挺高，10分鐘之內執行了300次，基本2秒鐘一次。

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
5,916.37	300	19.72	26.12	0.00	0.00		JDBC Thin Client	UPDATE ACCOUNT.......

透過load profile我們得知executes的頻率過高，所以我們在awr中檢視SQL ordered by Executions這個章節，可以得到執行頻率極高的sql語句，基本上查詢都是和subscriber,customer相關的。
執行頻率都很高，差距都不大，當我看到第10幾條記錄的時候，找到了關於ACCOUNT的select語句，執行頻率是很高的。

Executions	Rows Processed	Rows per Exec	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
43,436	43,415	1.00	16.25	30.07	70.72		JDBC Thin Client	select .... from ACCOUNT .....

透過以上的兩個部分，我們可以這麼理解，系統負載較高大部分原因都是基於IO，因為cpu使用率並不高，而資料庫讀的指標很高。相關sql語句的執行頻率也很高。這樣極為頻繁的訪問，造成了資料庫的負載很高。
而對於鎖的問題。我們可以看到在問題發生的時間段，session(7485,35335) 也在進行PUB_LOG的DML操作，同時也在進行ACCOUNT的DML操作。
而PUB_LOG這個表是歸屬於專門的daemon的，這個daemon要處理資料的時候就會總是阻塞。這樣就難怪資料處理的延遲了。
這樣問題的基本清晰了，剩下的部分就是和開發做確認了。
後續開發反饋在程式碼中發現了潛在的問題，會做進一步的跟蹤。

關於生產系統鎖問題的排查

相關文章