對於之前碰到的一個資料庫負載急劇提升的問題，做了應急處理之後，我們需要再冷靜下來，來看看是哪些地方出現了問題，還需要哪些改進。
首先第一個問題就是為什麼會突然負載提高，如果感覺，應該是業務層面出現了一些變化吧。當然沒有資料，日誌都是猜測。
我從監控中拿到了Zabbix監控的部分資料，發現在指定的時間點突然多了300多個程式。

而在資料庫的會話層面沒有發現任何的抖動，這一點就很難解釋的通了。
系統級不會平白無故出現300多個程式，這些程式主要是在忙些什麼，這些肯定說不通，我檢視了問題時間段的報警。發現了這麼一封報警資訊。

ZABBIX-監控系統:
------------------------------------
報警內容: Alive xxxx_p
------------------------------------
報警級別: PROBLEM
------------------------------------
監控專案: Alive：0
------------------------------------
報警時間:2016.07.08-11:16:03
    如果是這樣的情況就能說清楚了，在問題發生的時間段裡，因為系統延遲，orabbix無法從服務端抓取到資料，所以出現了Alive的報警，而那個時間段的資料還是會參考之前的資料，而Zabbix是客戶端的形式，在每臺伺服器上都有一個Agent，這些資料採集還是可以的，儘管延遲，但是還是會同步到服務端。因為我們是後續檢視的歷史資訊。所以這樣一來我們可以推理出來是在資料庫層面多了300個多會話。
    而在業務層面去解釋這個就比較困難了。首先業務層面的反饋是沒有異常的呼叫情況。而系統層面反饋也沒有發現特別的日誌。這個工作就無形中落到了資料庫層面。大家都希望我能夠給出一些解釋，能夠從資料庫層面得到一些分析的結果，畢竟這個問題是出現在資料庫端。這讓我聯想起之前工作中的一個有意思的故事，有兩個系統需要互動，系統會發資料到模組A,然後模組A會同步資料處理到模組B,以此類推，結果模組A的問題，模組A沒有錯誤日誌，模組B有錯誤日誌，這下大家都集中在模組B，然後讓他們提供更多的分析和解釋，最後發現問題是模組A那邊過來的，沒有錯誤日誌不證明沒錯誤，在這種多系統互動中就會有很多額外的溝通成本。
    當然這個問題也不是猜測出來的，我來看看資料庫端的情況。
    首先是SWAP的爭用，為什麼在問題時間段會突然出現爭用很高的情況，之前沒有嗎，實際情況是之前也有的，但是不夠明顯，那問題出現之前SWAP情況怎麼樣呢。檢視資料庫日誌發現了下面的一段。這麼一段日誌還是很有說服力的。
Archived Log entry 11780 added for thread 1 sequence 2581 ID 0xc5819545 dest 1:
Fri Jul 08 10:27:49 2016
WARNING: Heavy swapping observed on system in last 5 mins.
pct of memory swapped in [3.10%] pct of memory swapped out [0.54%].
Please make sure there is no memory pressure and the SGA and PGA
are configured correctly. Look at DBRM trace file for more details.
Fri Jul 08 10:28:13 2016
Thread 1 advanced to log sequence 2583 (LGWR switch)
Current log# 7 seq# 2583 mem# 0: /U01/app/oracle/fast_recovery_area/STEST032/onlinelog/o1_mf_7_blsdlk1p_.log
Fri Jul 08 10:28:13 2016
所以可以充分說明問題集中爆發之前已經有了SWAP的爭用情況。而後面的是一個集中的觸發點，導致了SWAP的爭用更加嚴重。
那麼問題發生時到底是哪些SQL或者資料庫層面的操作導致的問題呢，我一看快照，因為是殺掉程式重啟，那個時間段剛好沒有生成快照，導致了在問題發生時間段的ASH，AWR資料生成，所以只能看到之前一個小時的資料，我們可以作為一個參考。

SQL執行的大體情況如下。

SQL ID	PlanHash	Sampled # of Executions	% Activity	Row Source	% RwSrc	Top Event	% Event	SQL Text
	2802892098	219	31.29	MERGE	28.83	log file switch completion	24.86	MERGE INTO TEST_OPENPLATFORM_U...
ag4b2tb6yxscc	2802892098	219	31.29	TABLE ACCESS - BY INDEX ROWID	1.04	log file switch completion	1.04
		79	10.68	Row Source Not Available	10.68	log file switch completion	8.88	insert into TEST_USER_INFO (CI...
	2398546977	48	6.14	MERGE	5.01	log file switch completion	3.88	MERGE INTO CYUC_USER_LOGIN_TOK...
	167343150	10	3.97	TABLE ACCESS - FULL	3.12	CPU + Wait for CPU	3.12	MERGE INTO TEST_OPENPLATFORM_B...
	4261754961	16	3.50	TABLE ACCESS - FULL	3.31	CPU + Wait for CPU	3.31	MERGE INTO TEST_GUEST_USER_INF...

看到這個這個報告，我有些迷惑了，不知道問題的瓶頸在哪裡了，因為top 1的SQL本身已經最佳化過，已經是最優的方式了，執行頻率要高一些，而下面的兩個標黃的語句仔細檢視，是存在效能隱患的語句，但是執行頻率相對來說不高，佔用的比例也不高。
這樣一來問題的分析就有些茫然了。不過這邊也在和應用同學做一些確認。讓他們幫忙提供一些資料資訊。其中部分的資訊如下

      8點     9點     10點    11點    12點
/test/master   46279   43135   51140   42276   38712
/test/guest    1069    1313    1533    6148    1794
看到這些資料，在問題發生時間點，主要的執行頻率還下降了，看起來說明不了問題，不過有一點比較特別的就是/test/guest這個地方，平時的執行頻率是1000，而在問題發生時間點是6000多，這個確實是有些特別。
而從之前時間段的AWR可以看出，執行頻率還是1000多一些。

Elapsed Time (s)	Executions	Elapsed Time per Exec (s)	%Total	%CPU	%IO	SQL Id	SQL Module	SQL Text
1,521.05	6,464	0.24	22.07	0.72	1.94		JDBC Thin Client	MERGE INTO TEST_OPENPLATFORM_U...
69.84	1,980	0.04	1.01	6.77	8.20		JDBC Thin Client	MERGE INTO TEST_OPENPLATFORM_B...
507.27	1,304	0.39	7.36	3.32	0.00	351tx6bsgk1un	JDBC Thin Client	MERGE INTO TEST_GUEST_USER_INFO...

有了這些資料支撐，就可以明白問題的大體情況，原本系統的SWAP爭用已有，但是最近比較嚴重，而在問題發生時間段裡，問題更加嚴重，主要就是因為一個本來負載不是很高的SQL執行頻率從1000多提升到了6000多，執行計劃中顯示是全表掃描，好幾百萬資料的大表來說還是很明顯的問題。而對於這個語句的最佳化其實倒不是很難，關鍵有針對性的分析就尤為重要了。

資料庫負載急劇提高的應急處理(二)

相關文章