記錄一次伺服器宕機分析過程（1）-排查問題

02-27

發現宕機&啟動coredump

最近給版署審核版本用的伺服器每隔幾天就會宕機，情況比較類似，都是大廳服的進程直接沒有掉了。查看伺服器log，沒有發現什麼線索。懷疑是伺服器進程崩潰掉了，於是開啟了伺服器的coredump，等待下次宕機通過gdb查詢問題出在什麼地方。

coredump無效

過了幾天，伺服器再次宕機，查看coredump文件夾，發現並沒有生成dump文件。仔細想了一下，dump文件只有在程序崩潰時才會生成，那麼可能是程序沒有崩潰，而且通過其他方式退出了（自己退出，或者被kill）。

懷疑內存問題

這個時候想到內存問題，於是重啟伺服器運行一段時間後查看伺服器內存，果然發現伺服器進程中某個服務（一個服務運行在一個獨立的lua虛擬機上）內存佔用異常（佔用了幾百M，並且一直上漲）。為了驗證問題，手寫了一個10幾行代碼的C程序，不停申請內存並且不釋放。果然程序在吃光系統內存後閃退了，並且沒有產生coredump文件。留下列印信息：Memor已殺死。

引出OOM killer

google了一下這個列印信息，發現linux有一個叫做OOM-killer（Out Of Memory killer）的機制。

OOM killer會在系統內存耗盡的情況下觸發，選擇性的幹掉一些進程，以求釋放一些內存。OOM killer是通過/proc/<pid>/oom_score這個值來決定哪個進程被幹掉的。這個值是系統綜合進程的內存消耗量、CPU時間(utime + stime)、存活時間(uptime - start time)和oom_adj計算出的，消耗內存越多分越高，存活時間越長分越低。總之，總的策略是：損失最少的工作，釋放最大的內存同時不傷及無辜的用了很大內存的進程，並且殺掉的進程數盡量少。

找到系統日誌文件（/var/log/messages），發現幾條對應的信息：

Jul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Out of memory: Kill process 1119 (test) score 865 or sacrifice childJul 27 14:54:11 iZbp1gq49eb2h8qr5ktv1gZ kernel: Killed process 1119 (test) total-vm:962016kB, anon-rss:903972kB, file-rss:80kB

果然是OOM-killer殺死了我的例子程序，那麼log里會不會有伺服器進程被殺死的痕迹呢，繼續翻日誌，又發現幾條可疑的信息：

Jul 23 20:48:33 iZ23n1006xeZ kernel: [17045726.198604] mongod invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0...

這個時間點（Jul 23 20:48:33）列印的信息很長，大概意思是mongod觸發了OOM-killer。log里沒有遊戲伺服器進程相關的信息，而伺服器進程也確實是在Jul 23時間點附近掛掉的，應該是mongod觸發了OOM-killer，然後OOM-killer殺死了伺服器進程。為了確認伺服器掛掉的時間點和日誌信息產生的時間點吻和，我通過crontab起了一個定時shell腳本，用來監測伺服器進程的執行情況。繼續等待下次宕機。

追蹤內存泄漏

這個時候已經大概確定，是內存問題導致伺服器進程被殺死。於是開始追蹤內存的泄漏問題。

首先查看這個有問題的服務的代碼特徵，這個服務主要的工作是，不停的向中心伺服器請求最新的排行榜數據，並且替換本地的舊排行榜數據，也就是說在整個程序的執行過程中，會不停的產生大量的臨時內存。

然後，我觀察了一下這個服務的內存上漲特徵，發現它的內存是一直在周期上漲（內存上漲周期 == 請求數據的周期）的。是Lua GC失效了嗎？我在debug console輸入GC命令強制執行了一次GC（在後面的研究中明白，它實際是強制執行了一次完整的GC cycle），發現內存馬上降下來了，這說明內存是可以回收掉的。是GC無法被自動觸發嗎？

Lua GC

於是，研究了一下Lua的GC機制。根據lua官方文檔（www.lua.org/manual/5.3/manual.html#2.5）描述，Lua的GC實現了一個叫做incremental mark-and-sweep collector內存回收機制(http://wiki.luajit.org/New-Garbage-Collector)。大概意思就是一個基於三種狀態的可分步執行的GC機制，每個GC cycle可以分多個GC step完成。GC演算法可以設置兩個核心參數garbage-collector pause、garbage-collector step multiplier.；在官方文檔給出的對兩個參數的大概的解釋（具體的描述可以看官方文檔）是：

pause ：控制多久開始一次新的GC cycle，默認是200，表示內存是2（200/100）倍時開始一次新的GC cycle。

step multiplier ：GC速度相對於內存分配速度的倍數，默認是200，即2倍（200/100）。

單看以上的解釋還是很難理解這兩個參數，參看雲風對Lua GC分析的文檔（http://blog.codingnow.com/2011/03/lua_gc_3.html）。對兩個參數進一步的理解是：

pause：當前內存如果是估算的實際使用內存的（pause/100）倍時觸發GC cycle。比如，估算的實際使用的內存是100KB，當內存佔用達到200KB時會觸發GC cycle。
step multiplier：整個GC cycle是分多個GC step完成的，step multiplier調節每個GC step中會執行多少個GC single-step。

兩者的直觀意義是：

pause：越小，回收越積極（aggressive）；越大回收越不積極（less aggressive）。默認：200。
step multiplier：越小，回收越不積極（less aggressive）；越大回收越積極（aggressive）。默認：200。

接著，我寫了一個周期性執行，並且產生大量臨時內存的Lua程序，通過設置這兩個參數來看一下，這兩個參數對Lua GC的實際影響（X軸為執行次數；Y軸為程序內存單位KB）：

pause參數對比

隨著pause參數的擴大，GC cycle觸發周期變長，有更多垃圾內存未釋放。但是，對比沒有那麼穩定，跟Lua GC中部分核心變數是估算的有關係。

step multiplier參數對比

隨著step multiplier參數的增大，一次GC cycle執行時間變短，觸發周期也變短，垃圾內存會更快被回收。對step multiplier參數調低後，Lua GC非常敏感，第一次GC cycle的執行很久都沒有完成。

出問題服務的內存上漲狀態比較類似於（step multiplier=190）的曲線，一直處在上漲狀態，這大概是因為step multiplier不夠，一直無法完成第一次GC cycle。最後改動的方案是調高了那個服務的step multiplier（=300，ps：似乎高了些）。內存就不再持續上漲。

在這個宕機挖坑過程中，還是有幾個值得思考的地方：

為什麼伺服器進程運行幾天都無法完成第一次GC cycle？想了想，可能有幾點原因：
（1）第一次GC需要處理的垃圾內存本來就很大。
（2）Lua程序絕大部分時間都在休眠，導致GC cycle很少有執行機會（但是這個只是猜測）。
以上兩點導致很久沒都沒有完成第一次GC cycle。
Lua GC默認參數大部分情況是沒有問題的，但是對於需要平衡GC耗時和內存使用量的Lua程序，需要自己調整GC 參數。但是參數怎麼調才是好的，還是需要經過充分的實驗驗證。