南美叢林的一只蝴蝶煽動(dòng)翅膀，可能導(dǎo)致莫斯科下大雪，說(shuō)明的大氣系統(tǒng)的復(fù)雜性。而DBA在日常工作中葉經(jīng)常會(huì)面臨類似的問(wèn)題，我們從故障的表象上分析問(wèn)題處理問(wèn)題，而往往我們采取的措施僅僅是解決一些表象的問(wèn)題，并沒(méi)有找到問(wèn)題的關(guān)鍵。也就是說(shuō)，我們并沒(méi)有抓到扇翅膀的那只蝴蝶，而僅僅抓住了莫斯科上空的烏云。

前幾天碰到一個(gè)案例，寫出來(lái)和大家共享?？蛻粲幸惶紫到y(tǒng)下午1點(diǎn)多的時(shí)候，突然出現(xiàn)了故障，服務(wù)無(wú)法響應(yīng)，新會(huì)話連不上去。最后只能通過(guò)殺掉了大量的會(huì)話，才恢復(fù)正常。客戶想找到問(wèn)題的原因。找到我的時(shí)候已經(jīng)是下午的4點(diǎn)多了。出現(xiàn)故障的時(shí)段有大量這樣的信息：

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 

同時(shí)還存在一些類似的ORA-27XXX錯(cuò)誤：

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)場(chǎng)工程師認(rèn)為是BUG 6689903導(dǎo)致，建議關(guān)閉NUMA。客戶準(zhǔn)備晚上實(shí)施關(guān)閉NUMA的操作，想聽(tīng)聽(tīng)我的建議。我覺(jué)得關(guān)閉NUMA時(shí)一個(gè)十分大的操作，應(yīng)該十分謹(jǐn)慎，因此先要搞清楚到底是什么導(dǎo)致了今天的問(wèn)題。從ORA-27300來(lái)看，一般來(lái)說(shuō)是某種OS資源不足導(dǎo)致的問(wèn)題。因此我們首先要從分析錯(cuò)誤信息開(kāi)始，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是無(wú)法分配地址。對(duì)于BUG 6689903，Oracle官方解釋是使用了NUMA后，Oracle存在一個(gè)BUG，導(dǎo)致一個(gè)會(huì)話使用了大量的UDP端口，造成UDP端口不足?？梢酝ㄟ^(guò)打補(bǔ)丁或者關(guān)閉NUMA來(lái)解決這個(gè)問(wèn)題。而UDP端口耗盡也可能出現(xiàn)ERRNO =227，無(wú)法分配地址的錯(cuò)誤。因此可以初步判斷是由于UDP端口耗盡導(dǎo)致了問(wèn)題。在這種情況下打PATCH 6689903可以解決過(guò)多UDP端口被一個(gè)會(huì)話消耗的問(wèn)題，但是不一定能解決所有的問(wèn)題，當(dāng)系統(tǒng)負(fù)載進(jìn)一步加大（系統(tǒng)設(shè)置的PROCESSES=4500，而出故障時(shí)發(fā)現(xiàn)會(huì)話數(shù)無(wú)法突破1600）,可能還會(huì)出問(wèn)題。關(guān)閉NUMA雖然可以減少UDP端口的使用，但是會(huì)降低系統(tǒng)的性能，無(wú)法充分享受大型SMP系統(tǒng)的架構(gòu)優(yōu)勢(shì)，也是不足取的。因此較好的解決這個(gè)問(wèn)題是打PATCH 6689903，避免由于BUG過(guò)多消耗UDP端口，另外調(diào)整UDP端口的范圍，從而讓OS提供更多的UDP端口。通過(guò)下面命令：

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端口使用了缺省值，通過(guò)調(diào)整這兩個(gè)值，使中間的區(qū)間變大，就能提供更多的UDP端口號(hào)了。問(wèn)題分析道這里，看樣子已經(jīng)解決的差不多了?？赡艽蠖鄶?shù)DBA到此就大功告成了。而老白認(rèn)為其實(shí)不然，如果說(shuō)建議NUMA只是看到了下雪時(shí)莫斯科上空的烏云，那么分析到這里也僅僅看到了西伯利亞冷空氣的影響。離那只南美洲的蝴蝶還有萬(wàn)里之遙呢。

老白當(dāng)然會(huì)繼續(xù)分析下去，是什么原因?qū)е铝薝DP端口號(hào)被消耗光呢？客戶說(shuō)平時(shí)這個(gè)系統(tǒng)會(huì)話數(shù)在1000出頭，故障時(shí)會(huì)話數(shù)達(dá)到了1600。這個(gè)是UDP端口號(hào)被消耗光的一個(gè)很好的解釋。但是為什么會(huì)話數(shù)會(huì)突增呢?通過(guò)對(duì)應(yīng)用架構(gòu)的了解，我們知道這個(gè)系統(tǒng)的大多數(shù)應(yīng)用沒(méi)有采用連接池，而是客戶端直接連接的，當(dāng)系統(tǒng)處理能力下降時(shí)，客戶端連接數(shù)據(jù)庫(kù)的連接會(huì)增加，以適應(yīng)外部服務(wù)的請(qǐng)求。因此我們可以將懷疑點(diǎn)集中到系統(tǒng)出現(xiàn)了變慢的情況。如果在故障前的某個(gè)時(shí)段，系統(tǒng)突然變慢了，那么就有可能造成會(huì)話數(shù)增加的可能。會(huì)話數(shù)增加后，UDP端口配置過(guò)低的問(wèn)題就暴露出來(lái)了。

那么接下來(lái)我們就需要分析系統(tǒng)為什么會(huì)變慢，在什么時(shí)間變慢的。我們繼續(xù)分析ALERT LOG，發(fā)現(xiàn)第一次報(bào)錯(cuò)的時(shí)間是12點(diǎn)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] 

看樣子故障點(diǎn)應(yīng)該在12點(diǎn)41分之前。于是我們做一個(gè)ASH報(bào)告，來(lái)看看12：:00-12:40之間系統(tǒng)發(fā)生了什么，為了便于分析，我們先按照10分鐘周期做4個(gè)報(bào)告，在前面三個(gè)報(bào)告中，一切正常，在12:30-12:40的報(bào)告中，我們發(fā)現(xiàn)了一個(gè)疑點(diǎn)：

gcs drm freeze in enter server       24 

在1分鐘內(nèi)，活躍會(huì)話的采樣中，出現(xiàn)了24次drm的等待平均等待時(shí)間600毫秒左右。而且這個(gè)時(shí)間段內(nèi)的SQL執(zhí)行次數(shù)，BUFFER GET等指標(biāo)明顯低于前面的時(shí)段。因此我們可以初步斷定，這可能是導(dǎo)致會(huì)話數(shù)量突增的一個(gè)重要疑點(diǎn)。而這個(gè)系統(tǒng)的另外一個(gè)節(jié)點(diǎn)跑的是完全不同的應(yīng)用，而且還沒(méi)有投產(chǎn)，為什么會(huì)出現(xiàn)這么多DRM呢？通過(guò)LMD,LMON，LMS等的日志我們也看出，在12:36-38這段時(shí)間里的DRM數(shù)量比前面時(shí)段增加了數(shù)倍。于是我們?cè)诹硗庖粋€(gè)節(jié)點(diǎn)上的12:30-12:40生成了一個(gè)ASH報(bào)告，從這里我們終于看到了那只美麗的蝴蝶的真面目了，原來(lái)在這個(gè)時(shí)段，在另外一個(gè)節(jié)點(diǎn)上有人用SQLPLUS登陸上去，訪問(wèn)了大量的故障節(jié)點(diǎn)的數(shù)據(jù)。而這個(gè)操作導(dǎo)致了DRM事件增加，短暫降低了系統(tǒng)的性能。如果UDP端口號(hào)夠用，這個(gè)影響不會(huì)被放大，而僅僅會(huì)在12點(diǎn)多鐘業(yè)務(wù)不繁忙時(shí)段出現(xiàn)短暫幾分鐘的性能下降，很快就會(huì)平息。而正是由于UDP端口號(hào)不足，才放大了這個(gè)蝴蝶扇翅膀動(dòng)作。

抓住了這只蝴蝶，那么如何解決這個(gè)問(wèn)題就很明顯了，盡可能不要出現(xiàn)類似的操作肯定是要提的。不過(guò)另外一個(gè)問(wèn)題也是需要我們考慮的，在這樣的一個(gè)系統(tǒng)中，DRM其實(shí)是不必要的，因?yàn)檎Ｇ闆r下，兩個(gè)節(jié)點(diǎn)會(huì)跑自己的數(shù)據(jù)，不會(huì)交叉。因此關(guān)閉DRM是一個(gè)更靠譜的選擇。

大家可能對(duì)關(guān)閉DRM這個(gè)結(jié)局感到意外，不過(guò)如果你看過(guò)了這個(gè)抓蝴蝶的全過(guò)程，你就會(huì)認(rèn)為這是順理成章的事情了。

事情就是這么簡(jiǎn)單，但是我想大多數(shù)人只會(huì)走到這個(gè)過(guò)程中的某個(gè)步驟，就停下了。這就是DBA之間的差距，不僅僅是技術(shù)上的，更多的是態(tài)度的問(wèn)題。 
 
本文鏈接：http://www.oraclefans.cn/blog/showblog.jsp?rootid=32059
 

【編輯推薦】

1. 告訴你一些DBA求職面試技巧
2. 這些問(wèn)題，你能回答多少
3. 在牛人眼中 數(shù)據(jù)庫(kù)有何差異化又該如何選型
4. Oracle的安全標(biāo)記算不算bug