天天看點

Redis 源碼 bug 深入定位過程分享

Redis持久化包括RDB和AOF兩種方式,而采用AOF方式時Redis會定期重寫aof檔案以優化檔案結構并減少磁盤占用。為了使I/O操作不影響Redis對外提供服務,AOF重寫操作由子程序完成。然而,當系統配置中"vm.overcommit_memory = 0",且系統記憶體不足以fork子程序時,AOF重寫就無法啟動,而此之前已打開的pipe也永遠不會關閉,并在下一次嘗試AOF重寫時又建立新的pipe,進而造成fd洩漏。

這次,我們在對通路Redis的一個服務進行更新重新開機後遇到問題,該服務的日志出現大量通路Redis連接配接錯誤和逾時的資訊。随後,使用redis-cli也無法連接配接到Redis服務。在進一步分析了Redis服務端日志和運作資料後,我們大緻得出了問題産生的原因,并通過分析源碼确認了bug的存在。以下較長的描述此次問題的産生及定位過程。

首先描述一下出現故障的Redis執行個體的部署運作特征。此Redis執行個體是用于一項離線作業的隊列使用的,該作業每天跑一次。運作時,一個由crontab觸發的工具作為生産者會把需要處理的号碼推入Redis的list中,而另一個消費者工具則定時嘗試從list中取出号碼做相應處理。消費者消費速度遠慢于生産者,是以期間Redis的記憶體占用會達到一個極值。

當天對消費者服務(以下稱client)進行更新,增加了并行client數重新開機後(這點是問題暴漏的直接原因),發現log異常,報出很多網絡連接配接錯誤或接收逾時,但在更新前并沒有錯誤。因為client數遠小于Redis中maxclient=10000的設定,且使用的是TCP長連接配接方式,初步判斷是重新開機連接配接斷開後無法重新正常連接配接。

嘗試用Redis自帶用戶端redis-cli檢視伺服器運作狀态,同樣報錯"connect reset by peer",看來問題可能在服務端了。

首先檢查Redis執行個體的運作情況:CPU占用幾乎為0,記憶體占用也很低,程序啟動時間表明執行個體沒有重新開機。因為當時所有作業已經跑完,Redis中資料為空,是以這些名額正常。

然後檢視Redis服務的log,果然Redis的log頻繁報錯如下圖。日志很直接的給出了client連接配接失敗的原因是FD太大。

使用lsof指令檢查fd數,發現當時程序打開的fd數已經達到10128個,而其中大部分基本都是pipe:

Redis 源碼 bug 深入定位過程分享

而Redis中,pipe主要用于父子程序間通信,如AOF重寫、基于socket的RDB持久化等場景。難道是與某個子程序相關的調用出了問題?繼續回溯Redis服務端日志,發現果然在client更新重新開機前,3:45開始服務端日志已經出現異常,并在5:10左右log出現了變化:

分析日志可初步推測故障發生的過程:

在離線作業運作過程中,随着list中資料量增加,Redis記憶體占用逐漸增加;

當系統剩餘記憶體不足以fork子程序時,AOF重寫子程序啟動失敗,此時錯誤log為“Can't rewrite append only file in background: fork: Cannot allocate memory”,而用于父子程序通信的pipe不知什麼原因沒有關閉;

Redis不斷嘗試啟動AOF重寫子程序,終于在數小時後将允許的fd數耗盡,此時錯誤log為“Error opening /setting AOF rewrite IPC pipes: Numerical result out of range”;

與此同時,随着離線作業的完成,記憶體占用已經下降,但由于fd不足,AOF重寫子程序還是不能啟動;

注意到,被client長連接配接占用的socket fd在此過程中是一直沒有釋放的。直到更新client重新開機,釋放出了一部分fd,AOF重寫子程序成功運作,不再刷AOF相關的錯誤log;

client更新後,我們增加了client并行數,于是需要更多的socket fd來與client通信,但是目前空閑fd僅為之前client停止時釋放的數量,于是超出限制的client就無法正常運作了。是以,我們一開始就隻看到“Error registering fd event for the new client”這個錯誤。

這裡面有兩個問題待确定:

用于與子程序通信的pipe為何沒有被關閉

Redis中能打開的fd數量限制如何确定

随後我們直接分析源碼查找答案。

首先,我們定位到client連接配接報錯的主要調用鍊為 networking.c/acceptCommonHandler => networking.c/createClient => ae.c/aeCreateFileEvent:

而eventLoop->setsize則是在server.c/initServer中被初始化和設定的,大小為maxclient+128個。而我們maxclient采用Redis預設配置10000個,是以當fd=10128時就出錯了。

aof重寫過程由server.c/serverCron定時時間事件處理函數觸發,調用<code>aof.c/rewriteAppendOnlyFileBackground</code>啟動aof重寫子程序。在<code>rewriteAppendOnlyFileBackground</code>方法中我們注意到如果fork失敗,過程就直接退出了。

而關閉pipe的方法,是在server.c/serverCron =&gt; aof.c/backgroundRewriteDoneHandler 中發現AOF重寫子程序退出後被調用:

由此可見,如果aof重寫子程序沒有啟動,則pipe将不會被關閉。而下次嘗試啟動aof重寫時,又會調用aof.c/aofCreatePipes建立新的pipe。

解決方案

定位到問題後google相關關鍵字,發現這一問題早在2015年就被兩次在社群上報(參考 https://github.com/antirez/redis/issues/2857) ,2016年有開發者送出代碼修複此問題,直至2017年2月相關修複才被合入主幹(參考 https://github.com/antirez/redis/pull/3408) 。看來下一版本Redis才會修複此問題,真是一隻長壽的bug。

Tips:這隻長壽的bug在 3.2.9 版本已經修複了( 。→‿←。)

其實該問題發生機率不大,如果機器記憶體相對資料量足夠大,則無需理會。如果需要處理,一個方案可以參考官方修正方式修改代碼:在aof.c/rewriteAppendOnlyFileBackground中,啟動失敗時調用aof.c/aofClosePipes關閉打開的pipe。

不改代碼的規避方案:

設定linux系統的vm.overcommit_memory = 1(其意義可查閱man手冊,本文不再展開),盡量減少子程序fork失敗的情況;

設定Redis的maxmemory限制,當記憶體使用達到一定比例時不再接受新的資料;

使用主從備份,或bgsave持久化(RDB方式無此問題),關閉AOF持久化,等下一版本釋出。

此外,還可以通過監控手段及早發現問題。目前我們主要通過模調監控Redis服務的被調情況,而對于Redis本身運作狀況沒有監控措施。而此類問題,其實是可以通過監控Redis本身運作狀況及早發現的,這是下一步探索方向。