早上來到公司，照例進行了簡單的檢查，發現系統負載不高，就開始計劃一些sql tuning的工作，但是過了一會,在透過shell命令查詢一些sql資訊的時候，發現系統的反應有些慢，當時也沒在意，當我檢視v$session都開始慢的時候，感覺哪裡出了什麼問題了，最直觀的感受就是一些命令的執行都很緩慢了。
首先檢視了一下資料庫的負載，發現在最近的一個多小時內負載高了很多。幾乎是幾十倍的速度。

BEGIN_TIME------------------------- END_TIME--------------------------- ELAPSED_TIME- BTIME----- WORKLOAD_PER--------
----------------------------------- ----------------------------------- ------------- ---------- --------------------
15599 ** 20-OCT-14 01.00.05.479 AM 15600 ** 20-OCT-14 02.00.07.824 AM 60.039 266.29 443%
15600 ** 20-OCT-14 02.00.07.824 AM 15601 ** 20-OCT-14 03.00.10.947 AM 60.052 215.22 358%
15601 ** 20-OCT-14 03.00.10.947 AM 15602 ** 20-OCT-14 04.00.14.461 AM 60.059 214.85 357%
15602 ** 20-OCT-14 04.00.14.461 AM 15603 ** 20-OCT-14 05.00.18.115 AM 60.061 209.35 348%
15603 ** 20-OCT-14 05.00.18.115 AM 15604 ** 20-OCT-14 06.00.21.252 AM 60.052 962.13 1602%
15604 ** 20-OCT-14 06.00.21.252 AM 15605 ** 20-OCT-14 07.00.24.555 AM 60.055 599.99 999%
15605 ** 20-OCT-14 07.00.24.555 AM 15606 ** 20-OCT-14 08.00.26.581 AM 60.034 549.54 915%
15606 ** 20-OCT-14 08.00.26.581 AM 15607 ** 20-OCT-14 09.00.29.611 AM 60.051 1391.88 2317%
15607 ** 20-OCT-14 09.00.29.611 AM 15608 ** 20-OCT-14 10.00.32.189 AM 60.043 1213.72 2021%
15608 ** 20-OCT-14 10.00.32.189 AM 15610 ** 20-OCT-14 11.38.00.930 AM 97.479 24637.09 25274%
15609 ** 20-OCT-14 11.00.39.281 AM 15610 ** 20-OCT-14 11.38.00.930 AM 37.361 18493.3 49499%

然後檢視一些效能檢視都開始變得極為緩慢，最後連生成awr報告的時候每一個步驟都得反應十多秒了。

首先排除了資料庫中的鎖問題的可能性,然後開始排查倒底是儲存的IO問題還是資料庫級的?
先從系統級來看，系統級的IO情況。
檢視dd命令的效果時，發現系統的IO出現了嚴重的問題。使用dd命令在正常的情況下每秒差不多有500~700M/s的速度。現在IO基本是癱瘓的感覺。
1000+0 records out
1048576000 bytes (1.0 GB) copied, 94.1975 seconds, 11.1 MB/s
------------------------------
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 334.724 seconds, 3.1 MB/s
------------------------------
1000+0 records in
1000+0 records out
1048576000 bytes (1.0 GB) copied, 33.5012 seconds, 31.3 MB/s
------------------------------

透過如上的dd結果還不能確定。在資料庫級的IO出現呢嚴重等待的時候也是會導致系統級的問題。
從這個思路來看，這個問題和cpu的問題關聯不是很大.
透過sar來檢視io的情況。IOwait也是突然增高的。
10:40:02 AM CPU %user %nice %system %iowait %steal %idle
10:50:01 AM all 21.60 0.00 4.40 0.37 0.00 73.63
11:00:01 AM all 13.94 0.00 3.55 4.57 0.00 77.94
11:10:01 AM all 8.55 0.00 2.66 5.78 0.00 83.01
11:20:02 AM all 12.06 0.00 3.22 8.71 0.00 76.01
11:30:01 AM all 9.51 0.00 2.45 10.82 0.00 77.23
11:40:01 AM all 9.75 0.00 2.55 11.51 0.00 76.19
11:50:02 AM all 7.00 0.00 2.40 12.02 0.00 78.57

有了這些思路，可以感覺可能是在特定的一個時間點裡資料庫裡有什麼動作才導致的系統的負載極具提高。
檢視了top命令的結果再次得到了一些印證。
因為透過top命令，可以看到不少ora_P0xxx的程式,這個程式就是資料庫中存在並行的操作。看到並行程式達到了90多個。
這個時候看到那麼到的程式，如果想知道到底是哪些session在做並行的操作，可以根據如下的sql來簡單查詢到一些有用的資訊。
select pxsess.sid||','||pxsess.serial# sess_id,sess.username,sess.osuser,sess.machine,sess.program,pxsess.qcsid,pxsess.qcserial#,pxsess.degree,pxsess.server#,pxsess.req_degree from v$px_session pxsess,v$session sess where pxsess.sid=sess.sid ;

得到的結果類似下面的樣子。其實得到的session結果比這個多很多，我選了幾個列舉說明情況。
可以看到並行度為4,有很大一部分都是從客戶端scanner@client1發過來的。這樣的session有10多個。
SESS_ID USERNAME OSUSER MACHINE PROGRAM QCSID QCSERIAL# DEGREE SERVER# REQ_DEGREE
--------------- --------------- --------------- -------------------- ------------------------- ---------- ---------- ---------- ---------- ----------
3060,19215 PRDUSER prdwrk01 client1 oracle@dbmachine (P000) 6912 12521 4 1 4
5903,31549 PRDUSER prdwrk01 client1 oracle@dbmachine (P001) 6912 12521 4 2 4
6338,17097 PRDUSER prdwrk01 client1 oracle@dbmachine (P002) 6912 12521 4 3 4
3670,37601 PRDUSER prdwrk01 client1 oracle@dbmachine (P003) 6912 12521 4 4 4
5963,10235 PRDUSER prdwrk01 client1 oracle@dbmachine (P004) 6912 12521 4 1 4
6289,37919 PRDUSER prdwrk01 client1 oracle@dbmachine (P005) 6912 12521 4 2 4
432,51019 PRDUSER prdwrk01 client1 oracle@dbmachine (P006) 6912 12521 4 3 4
3299,17439 PRDUSER prdwrk01 client1 oracle@dbmachine (P007) 6912 12521 4 4 4
3894,9907 PRDUSER prdwrk01 client1 oracle@dbmachine (P008) 497 18425 2 1 2
4403,13615 PRDUSER prdwrk01 client1 oracle@dbmachine (P009) 497 18425 2 2 2
400,25915 PRDUSER prdwrk01 client1 oracle@dbmachine (P010) 497 18425 2 1 2
6509,61063 PRDUSER prdwrk01 client1 oracle@dbmachine (P011) 497 18425 2 2 2
6912,12521 PRDUSER prdwrk01 client1 scanner@client1 (TNS V1-V3) 6912
497,18425 PRDUSER prdwrk01 client2 JDBC Thin Client 497

透過session來查詢對應的sql語句，發現是一個比較大的查詢,這個查詢中使用了Hint來做幾個大表的全表掃描,大表都是千萬級的表,所以同時十多個session做並行，而且都是做幾個大表的全表掃描,資料庫級就是嚴重的io等待，反應到系統級,又使用了並行,會消耗極高的系統IO.
而且根據我的瞭解，這個查詢時產品線中使用的,目前是最快的執行就是需要走全表掃描，但是隻需要在個別的client中部署即可，這一下子執行了這麼多，確實有點異常。和客戶那邊協調過之後，他們馬上從package裡面停掉了多餘的程式。IO速度一下子好了起來。
在這個過程中，awr報告終於生成了。就來再次印證一下這個問題吧。
首先系統的負載很高，這個沒有問題。

Elapsed:		60.12 (mins)
DB Time:		6,143.79 (mins)

從整體的Profile來看

系統的物理讀很高。每秒達到了105,583.8,確實是一個很高的值了。

Physical reads:

105,583.8

2,166.4

在來看看等待事件,就很清楚了。全是Io相關的。

Event	Waits	Time(s)	Avg wait (ms)	% DB time	Wait Class
db file sequential read	21,816,629	178,657	8	48.47	User I/O
direct path read	1,786,153	60,763	34	16.48	User I/O
read by other session	1,830,998	31,137	17	8.45	User I/O
log file sync	216,111	25,437	118	6.90	Commit
DB CPU		21,645		5.87

檢視time model的時候,可以看到絕大部分的時間都在sql語句的執行上了。

Statistic Name	Time (s)	% of DB Time
sql execute elapsed time	339,415.91	92.08
DB CPU	21,644.80	5.87

而且這個過程中IO部分佔到了70%以上的消耗。

Wait Class	Waits	%Time -outs	Total Wait Time (s)	Avg wait (ms)	%DB time
User I/O	26,965,785	0	285,901	11	77.56

從上面可以得到，是有一些高IO wait的sql導致了系統極高的物理讀,出現了嚴重的IO等待。
所以在檢視sql details的時候直接檢視IO wait就可以了。

最後看到前3個都是和那個scanner相關的sql語句。

User I/O Time (s)	Executions	UIO per Exec (s)	%Total	Elapsed Time (s)	%CPU	%IO	SQL Id	SQL Module	SQL Text
19,045.53	42	453.47	6.66	20,884.74	5.34	91.19	4gz51fphuarsw	JDBC Thin Client	/* scanner.....
16,439.97	43	382.32	5.75	17,683.92	3.00	92.97	6fu3z8pqd2y9g	JDBC Thin Client	/* scanner.....
16,346.01	43	380.14	5.72	16,687.58	2.76	97.95	fg5mc598u799u	JDBC Thin Client	select /*+ leading (xxxxbpm...

在停掉了額外消耗的客戶端程式後，系統的負載就恢復了正常。
透過這個案例也可以得出,並行的使用也是需要考量的,而且需要平衡系統的資源使用情況。可能看似很小的一個問題放大就是一個很嚴重的問題。

由一條sql語句導致的系統IO問題

相關文章