如何抓住蝴蝶效應(yīng)中的那只蝴蝶
南美叢林的一只蝴蝶煽動翅膀,可能導(dǎo)致莫斯科下大雪,說明的大氣系統(tǒng)的復(fù)雜性。而DBA在日常工作中葉經(jīng)常會面臨類似的問題,我們從故障的表象上分析問題處理問題,而往往我們采取的措施僅僅是解決一些表象的問題,并沒有找到問題的關(guān)鍵。也就是說,我們并沒有抓到扇翅膀的那只蝴蝶,而僅僅抓住了莫斯科上空的烏云。
前幾天碰到一個案例,寫出來和大家共享??蛻粲幸惶紫到y(tǒng)下午1點多的時候,突然出現(xiàn)了故障,服務(wù)無法響應(yīng),新會話連不上去。最后只能通過殺掉了大量的會話,才恢復(fù)正常??蛻粝胝业絾栴}的原因。找到我的時候已經(jīng)是下午的4點多了。出現(xiàn)故障的時段有大量這樣的信息:
- Mon Apr 11 12:52:24 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_10410.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:01 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13426.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13934.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13936.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27504: IPC error creating OSD context
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:55:25 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_13938.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27504: IPC error creating OSD context
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:56:00 2011
- Thread 2 advanced to log sequence 2945 (LGWR switch)
- Current log# 4 seq# 2945 mem# 0: /redolog/sjzzw2/redo04.log
- Mon Apr 11 12:56:01 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_14554.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
同時還存在一些類似的ORA-27XXX錯誤:
- Mon Apr 11 12:56:33 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_22957.trc:
- ORA-27509: IPC error receiving a message
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
- ORA-27301: OS failure message: Socket operation on non-socket
- ORA-27302: failure occurred at: sskgxprcv1
- Mon Apr 11 12:56:33 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_25431.trc:
- ORA-27509: IPC error receiving a message
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
- ORA-27301: OS failure message: Socket operation on non-socket
- ORA-27302: failure occurred at: sskgxprcv1
- Mon Apr 11 12:57:24 2011
根據(jù)
- ORA-27300: OS system dependent operation:recvmsg failed with status: 216
現(xiàn)場工程師認(rèn)為是BUG 6689903導(dǎo)致,建議關(guān)閉NUMA。客戶準(zhǔn)備晚上實施關(guān)閉NUMA的操作,想聽聽我的建議。我覺得關(guān)閉NUMA時一個十分大的操作,應(yīng)該十分謹(jǐn)慎,因此先要搞清楚到底是什么導(dǎo)致了今天的問題。從ORA-27300來看,一般來說是某種OS資源不足導(dǎo)致的問題。因此我們首先要從分析錯誤信息開始,HP-UX的ERRNO=227,216
- # define ENOTSOCK 216 /* Socket operation on non-socket */
- # define EADDRNOTAVAIL 227 /* Can't assign requested address */
216是在非SOCKET上操作SOCKET操作,227是無法分配地址。對于BUG 6689903,Oracle官方解釋是使用了NUMA后,Oracle存在一個BUG,導(dǎo)致一個會話使用了大量的UDP端口,造成UDP端口不足??梢酝ㄟ^打補(bǔ)丁或者關(guān)閉NUMA來解決這個問題。而UDP端口耗盡也可能出現(xiàn)ERRNO =227,無法分配地址的錯誤。因此可以初步判斷是由于UDP端口耗盡導(dǎo)致了問題。在這種情況下打PATCH 6689903可以解決過多UDP端口被一個會話消耗的問題,但是不一定能解決所有的問題,當(dāng)系統(tǒng)負(fù)載進(jìn)一步加大(系統(tǒng)設(shè)置的PROCESSES=4500,而出故障時發(fā)現(xiàn)會話數(shù)無法突破1600),可能還會出問題。關(guān)閉NUMA雖然可以減少UDP端口的使用,但是會降低系統(tǒng)的性能,無法充分享受大型SMP系統(tǒng)的架構(gòu)優(yōu)勢,也是不足取的。因此較好的解決這個問題是打PATCH 6689903,避免由于BUG過多消耗UDP端口,另外調(diào)整UDP端口的范圍,從而讓OS提供更多的UDP端口。通過下面命令:
- oracle@sjzzw22:/usr/include/sys$ ndd -get /dev/udp udp_largest_anon_port
- 65535
- oracle@sjzzw22:/usr/include/sys$ ndd -get /dev/udp udp_smallest_anon_port
- 49152
我們看到系統(tǒng)的UDP端口使用了缺省值,通過調(diào)整這兩個值,使中間的區(qū)間變大,就能提供更多的UDP端口號了。問題分析道這里,看樣子已經(jīng)解決的差不多了??赡艽蠖鄶?shù)DBA到此就大功告成了。而老白認(rèn)為其實不然,如果說建議NUMA只是看到了下雪時莫斯科上空的烏云,那么分析到這里也僅僅看到了西伯利亞冷空氣的影響。離那只南美洲的蝴蝶還有萬里之遙呢。
老白當(dāng)然會繼續(xù)分析下去,是什么原因?qū)е铝薝DP端口號被消耗光呢?客戶說平時這個系統(tǒng)會話數(shù)在1000出頭,故障時會話數(shù)達(dá)到了1600。這個是UDP端口號被消耗光的一個很好的解釋。但是為什么會話數(shù)會突增呢?通過對應(yīng)用架構(gòu)的了解,我們知道這個系統(tǒng)的大多數(shù)應(yīng)用沒有采用連接池,而是客戶端直接連接的,當(dāng)系統(tǒng)處理能力下降時,客戶端連接數(shù)據(jù)庫的連接會增加,以適應(yīng)外部服務(wù)的請求。因此我們可以將懷疑點集中到系統(tǒng)出現(xiàn)了變慢的情況。如果在故障前的某個時段,系統(tǒng)突然變慢了,那么就有可能造成會話數(shù)增加的可能。會話數(shù)增加后,UDP端口配置過低的問題就暴露出來了。
那么接下來我們就需要分析系統(tǒng)為什么會變慢,在什么時間變慢的。我們繼續(xù)分析ALERT LOG,發(fā)現(xiàn)第一次報錯的時間是12點41分左右:
- Mon Apr 11 12:38:06 2011
- Thread 2 advanced to log sequence 2940 (LGWR switch)
- Current log# 3 seq# 2940 mem# 0: /redolog/sjzzw2/redo03.log
- Mon Apr 11 12:40:58 2011
- Errors in file /oracle/app/oracle/admin/sjzzw2/udump/sjzzw22_ora_25451.trc:
- ORA-00603: ORACLE server session terminated by fatal error
- ORA-27544: Failed to map memory region for export
- ORA-27300: OS system dependent operation:bind failed with status: 227
- ORA-27301: OS failure message: Can't assign requested address
- ORA-27302: failure occurred at: sskgxpcre3
- Mon Apr 11 12:40:59 2011
- Trace dumping is performing id=[cdmp_20110411124059]
看樣子故障點應(yīng)該在12點41分之前。于是我們做一個ASH報告,來看看12::00-12:40之間系統(tǒng)發(fā)生了什么,為了便于分析,我們先按照10分鐘周期做4個報告,在前面三個報告中,一切正常,在12:30-12:40的報告中,我們發(fā)現(xiàn)了一個疑點:
- gcs drm freeze in enter server 24
在1分鐘內(nèi),活躍會話的采樣中,出現(xiàn)了24次drm的等待平均等待時間600毫秒左右。而且這個時間段內(nèi)的SQL執(zhí)行次數(shù),BUFFER GET等指標(biāo)明顯低于前面的時段。因此我們可以初步斷定,這可能是導(dǎo)致會話數(shù)量突增的一個重要疑點。而這個系統(tǒng)的另外一個節(jié)點跑的是完全不同的應(yīng)用,而且還沒有投產(chǎn),為什么會出現(xiàn)這么多DRM呢?通過LMD,LMON,LMS等的日志我們也看出,在12:36-38這段時間里的DRM數(shù)量比前面時段增加了數(shù)倍。于是我們在另外一個節(jié)點上的12:30-12:40生成了一個ASH報告,從這里我們終于看到了那只美麗的蝴蝶的真面目了,原來在這個時段,在另外一個節(jié)點上有人用SQLPLUS登陸上去,訪問了大量的故障節(jié)點的數(shù)據(jù)。而這個操作導(dǎo)致了DRM事件增加,短暫降低了系統(tǒng)的性能。如果UDP端口號夠用,這個影響不會被放大,而僅僅會在12點多鐘業(yè)務(wù)不繁忙時段出現(xiàn)短暫幾分鐘的性能下降,很快就會平息。而正是由于UDP端口號不足,才放大了這個蝴蝶扇翅膀動作。
抓住了這只蝴蝶,那么如何解決這個問題就很明顯了,盡可能不要出現(xiàn)類似的操作肯定是要提的。不過另外一個問題也是需要我們考慮的,在這樣的一個系統(tǒng)中,DRM其實是不必要的,因為正常情況下,兩個節(jié)點會跑自己的數(shù)據(jù),不會交叉。因此關(guān)閉DRM是一個更靠譜的選擇。
大家可能對關(guān)閉DRM這個結(jié)局感到意外,不過如果你看過了這個抓蝴蝶的全過程,你就會認(rèn)為這是順理成章的事情了。
事情就是這么簡單,但是我想大多數(shù)人只會走到這個過程中的某個步驟,就停下了。這就是DBA之間的差距,不僅僅是技術(shù)上的,更多的是態(tài)度的問題。
本文鏈接:http://www.oraclefans.cn/blog/showblog.jsp?rootid=32059
【編輯推薦】