由hugepage設定導致的資料庫事故

dbhelper發表於2015-01-31

近期客戶希望提高業務處理能力,在現有的環境中加入幾臺weblogic伺服器,所以需要增加一下連線數的配置,但是同時他們想對現有系統的設定一些變更,最後傳送了一個清單給我們。
大體的變更如下:

Change Processes from 10000 to 18000

Change PGA from 10G to 20G

Change Buffer Cache from 20G to 40G

Change Shared pool from 10G to 20G

HugePage from 60 GB to 120GB
大體看了下沒有什麼問題,他們就去做了,等到今天早上的時候,檢視資料庫的負載,沒有發現什麼問題。但是使用top命令的時候發現近300G的記憶體,怎麼只剩下50G了。
top - 10:21:47 up 43 days,  8:14,  2 users,  load average: 29.35, 29.56, 25.51
Tasks: 4524 total,  11 running, 4508 sleeping,   0 stopped,   5 zombie
Cpu(s):  3.0%us,  0.9%sy,  0.0%ni, 95.9%id,  0.1%wa,  0.0%hi,  0.2%si,  0.0%st
Mem:  288568372k total, 235419644k used, 53148728k free,  1982988k buffers
Swap: 377487328k total,        0k used, 377487328k free, 66761268k cached
這個問題有些奇怪,這臺伺服器上還跑著幾臺資料庫例項,但是據我所知,消耗的快取其實並不大,其它幾個庫的sga都在10G以內。
使用ipcs -a 來檢視共享記憶體段的問題。
------ Shared Memory Segments --------
key        shmid      owner      perms      bytes      nattch     status
0x00000000 251789314  root      644        80         2
0x00000000 251822084  root      644        16384      2
0x00000000 251854853  root      644        280        2
0x5500025e 251887622  root      644        256064     1                 locked
0xdb22d1bc 252182538  xxxxx1     660        3340763136 31
0x91442618 252248075  xxxxxx2  660        4096       0
0xba17ff18 252510220  oraccbs1  660        68067262464 3073
0xd9152b54 252379149  oraarcs1  660        3542089728 36
...
使用vmstat來檢視
> vmstat 1 2
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
16  0      0 51928680 1983028 67193648    0    0   349   452    0    0  3  1 96  0  0
15  0      0 51898956 1983028 67195296    0    0 75000  8015 43425 108231 12  6 81  0  0
使用free -m來檢視。
> free -m
             total       used       free     shared    buffers     cached
Mem:        281805     225747      56057          0       1936      65625
-/+ buffers/cache:     158185     123619
Swap:       368639          0     368639
這個時候從業務部門和開發部門的反饋來說還沒有什麼問題,所以就準備吃個飯回來繼續查。
過了一會回來的時候,連線資料庫時發現資料庫一下子特別慢,敲一個命令都得等好一會兒才能返回結果。
馬上使用top檢視系統情況,發現剩餘程式只有500M左右了。
> top -c
top - 12:23:12 up 43 days, 10:15, 13 users,  load average: 301.41, 205.59, 166.94
Tasks: 6701 total, 144 running, 6549 sleeping,   0 stopped,   8 zombie
Cpu(s):  2.8%us, 95.2%sy,  0.0%ni,  1.6%id,  0.1%wa,  0.0%hi,  0.2%si,  0.0%st
Mem:  288568372k total, 288021512k used,   546860k free,     1108k buffers
Swap: 377487328k total, 10312300k used, 367175028k free, 64311712k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
28855 root      11  -5     0    0    0 S 84.9  0.0 728:45.31 [vxfs_thread]
30951 oraccbs1  25   0 63.6g 7.1g 7.1g R 58.7  2.6   4:44.29 ora_p025_CUST01
3852 root      20  -5     0    0    0 R 52.2  0.0  22:53.66 [kswapd3]
3849 root      20  -5     0    0    0 R 52.1  0.0   7:12.63 [kswapd0]
3851 root      20  -5     0    0    0 R 52.1  0.0  17:42.67 [kswapd2]
3850 root      20  -5     0    0    0 R 52.1  0.0   8:09.50 [kswapd1]
31028 oraccbs1  25   0 63.6g 5.9g 5.9g R 37.7  2.2   5:12.19 ora_p027_CUST01
31273 oraccbs1  19   0 63.6g 206m 203m R 35.6  0.1   0:09.73 oracleCUST01 (LOCAL=NO)
30511 oraccbs1  25   0 63.6g 4.3g 4.3g R 34.6  1.6   8:32.08 ora_p004_CUST01
21481 tivoliam  15   0  977m 255m 5248 S 27.2  0.1   6338:00 /opt/app/IBM/ITM/lx8266/lz/bin/klzagent
29115 oraccbs1  18   0 18008 6392  812 R 27.2  0.0   0:53.76 top -c
32090 oraccbs1  25   0 63.6g  69m  67m R 26.7  0.0   0:05.92 oracleCUST01 (LOCAL=NO)
31332 oraccbs1  18   0 63.6g  26m  18m S 23.9  0.0   0:08.28 ora_p171_CUST01

從程式來看,出現了幾個kswapd的top程式還有一些並行相關的程式。
從ipcs的情況來看,程式數從原來的3000多個增長到了5000多個,這個是由於一些後臺的job和daemon啟動了的原因,除此之外沒有發現其它的不同。
------ Shared Memory Segments --------
key        shmid      owner      perms      bytes      nattch     status
0x00000000 251789314  root      644        80         2
0x00000000 251822084  root      644        16384      2
0x00000000 251854853  root      644        280        2
0x5500025e 251887622  root      644        256064     1                 locked
0xdb22d1bc 252182538  xxxxx    660        3340763136 32
0x91442618 252248075  xxxxxxx  660        4096       0
0xba17ff18 252510220  oraccbs1  660        68067262464 5207
0xd9152b54 252379149  oraarcs1  660        3542089728 35

來看看奇怪的kswapd程式的說明。
Linux uses kswapd for virtual memory management such that pages that have been recently accessed are kept in memory and less active pages are paged out to disk.
這個和虛擬記憶體管理相關,存在著大量的頁面置換。如果驗證這一點,可以從vmstat來說明。
> vmstat 1 3
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
611  7 10799976 547000   1444 64194804    0    0   351   452    0    0  3  1 96  0  0
536  1 10799984 546716   1508 64194876  252  108   614   361 1062 108275  7 93  1  0  0
428  2 10800060 548112   1516 64195268   48  204   436   437 1052 111422  9 86  5  0  0
swpd的值在之前都是為0,說明存在著大量的置換操作。
從業務部門和開發部門的一些同事反饋,資料庫已經連不上了。
這個時候我趕快傳送了一封郵件抄給客戶的dba組,讓他們趕緊檢視一些記憶體異常的問題,同時我在遠端也在看。這樣問題就不會很被動,同步一些資訊給客戶,可能他們已經在關注或者在查了,能避免很多的誤解。
我比對了核心引數的設定發現,核心引數沒有任何的變化。
主要的核心引數透過cat /etc/sysctl.conf來檢視
排除了核心引數變更帶來的影響,來看看並行程式,檢視此時系統中並行程式大概有170多個,這對系統確實是比較高的負載,但是從近這些天的負載來看,每天都有一個時間段內會啟用一些Job,daemon。有幾個job在啟動的時候會消耗大量的cpu,io資源,已經在產品級做了最佳化,但是持續的時間不會太長,大概10多分鐘就正常了,這個問題從發現到現在已經持續了將近半個多小時了。
而且設定了較大的buffer cache,shared pool已經效果更好才對。所以從程式的角度來說,沒有任何變化,不會有明確的原因是由於程式中的並行導致的。
這個時候問題陷入了僵局,但是需要快速給出一些解決方案。
從頭開始來看,出現kswapd3的的原因是由於記憶體使用緊張導致的,那麼300G左右的記憶體,設定了60G左右的Hugepage,怎麼還不夠用呢,從Hugepage的情況來看一下。
> cat /proc/meminfo | grep -i page
AnonPages:    21223132 kB
PageTables:   136301560 kB
HugePages_Total: 30000
HugePages_Free:  27284
HugePages_Rsvd:    566
Hugepagesize:     2048 kB
這一看確實讓人奇怪,設定了那麼大的hugepage怎麼還剩餘這麼多呢,基本都沒有用到。
怎麼能夠證明在hugepage的設定出現問題呢,
一個原因就是客戶傳送的變更清單,HugePage from 60 GB to 120GB ,清單上說需要變更為60G到120G,但是從目前的情況來看,似乎這個變更沒有設定或是沒有生效。
如果放開一步說,60G的變更沒有設定為120G,怎麼能夠證明60G是錯誤的呢。
這個時候還是得靠日誌,資料庫啟動的時候會產生一些hugepage相關的資訊。
正常情況下,如果hugepage設定正常,可以從資料庫的日誌中我們發現如下的一段內容。
Starting ORACLE instance (normal)
****************** Huge Pages Information *****************
Huge Pages memory pool detected (total: 30000 free: 28822)
DFLT Huge Pages allocation successful (allocated: 17025)
***********************************************************
但是從昨天查到的資料庫日誌內容如下:
Instance terminated by USER, pid = 6885
Tue Jan 27 01:03:18 2015
Starting ORACLE instance (normal)
****************** Huge Pages Information *****************
Huge Pages memory pool detected (total: 30000 free: 27287)
Huge Pages allocation failed (free: 29431 required: 32457)
Allocation will continue with default/smaller page size
**********************************************************
這樣一來問題就很明顯了,我們來做一個簡單的演算。
昨晚的變更如下:

Change Processes from 10000 to 18000

Change PGA from 10G to 20G

Change Buffer Cache from 20G to 40G

Change Shared pool from 10G to 20G

HugePage from 60 GB to 120GB 
那麼SGA為20+40G+(large_pool+stream_pool+java_pool.....) >60G
而根據錯誤日誌的推算每個hugepage大小為2M,需要32457個,那麼大小就是32457*2M=64914M
而設定的最大值為60G,所以無法啟用從而導致了系統的嚴重問題。
最後和客戶商量,他們把SGA,PGA的大小都恢復到原有的值,保證能夠穩定執行的前提下,稍後再安排做hugepage的最佳化。最後把這個庫failover到另外一臺server中,再次檢視就沒有問題了。
使用top命令的結果如下:
Tasks: 5238 total,  14 running, 5218 sleeping,   0 stopped,   6 zombie
Cpu(s): 14.2%us,  4.1%sy,  0.0%ni, 80.1%id,  0.1%wa,  0.2%hi,  1.3%si,  0.0%st
Mem:  363033360k total, 97577104k used, 265456256k free,   770016k buffers
Swap: 377487328k total,        0k used, 377487328k free, 13109108k cached
這個問題帶給大家的反思就是任何細小的問題都可能帶來嚴重的系統影響,需要認真評估,才能把問題扼殺在搖籃裡。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/8494287/viewspace-1421999/,如需轉載,請註明出處,否則將追究法律責任。

相關文章