乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

雲端計算頻道發表於2018-12-14

作者簡介

 

李劍,攜程技術保障中心繫統研發部資深軟體工程師,負責Redis和Mysql的容器化和服務化工作,以及維護容器宿主機的核心版本,喜歡深入分析系統疑難雜症。

容器化對於Redis自動化運維效率、資源利用率方面都有巨大提升,攜程在對Redis在容器上效能和穩定性進行充分驗證後,啟動了生產Redis遷移容器化的專案。其中第一批次兩臺宿主機,第二批次五臺宿主機。

本次“異常”是第二批次遷移過程中發現的,排查過程一波三折,最終得出讓人吃驚的結論。

希望本次結論能給遇到同樣問題的小夥伴以啟發,另外本次分析問題的思路對於分析其他疑難雜症也有一定借鑑作用。

一、問題描述

在某次Redis遷移容器後,DBA發來告警郵件,slowlog>500ms,同時在DBA的慢日誌查詢裡可以看到有1800ms左右的日誌,如下圖1所示:


乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖1


二、分析過程

2.1 什麼是slowlog

在分析問題之前,先簡單解釋下Redis的slowlog。閱讀Redis原始碼(圖2)不難發現,當某次Redis的操作大於配置中slowlog-log-slower-than設定的值時,Redis就會將該值記錄到記憶體中,透過slowlog get可以獲取該次slowlog發生的時間和耗時,圖1的監控資料也是從此獲得。

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖2

也就是說,slowlog只是單純的計算Redis執行的耗時時間,與其他因素如網路之類的都沒關係

2.2 矛盾的日誌

每次slowlog都是1800+ms並且都隨機出現,在第一批次Redis容器化的宿主機上完全沒有這種現象,而QPS遠小於第一批次遷移的某些叢集,按常理很難解釋,這時候翻看CAT記錄,更加加重了我們的疑惑,見圖3:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖3

CAT是攜程根據開源軟體()的定製版本,用於客戶端記錄打點的耗時,從圖中可以很清晰的看到,Redis打點的最大值367ms也遠小於1800ms,它等於是說下面這張自相矛盾圖,見圖4:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖4

2.3 求助社群

所以說,slowlog問題要麼是CAT誤報,要麼是Redis誤報,但Redis使用如此廣泛,並且經過詢問CAT的維護者說CAT有一定的訊息丟棄率,而Redis在官方github issue中並沒有發現類似的slowlog情形,因此我們第一感覺是CAT誤報,並在官方Redis issue中提問,試圖獲取社群的幫助。

很快社群有人回覆,可能是NUMA架構導致的問題,但也同時表示NUMA導致slowlog高達1800ms很不可思議。關於NUMA的資料網上有很多,這裡不再贅述,我們在查閱相關NUMA資料後也發現,NUMA架構導致如此大的slowlog不太可能,因此放棄了這條路徑的嘗試。

2.4 豁然開朗

看上去每個方面好像都沒有問題,而且找不到突破口,排障至此陷入了僵局。

重新閱讀Redis原始碼,直覺發現gettimeofday()可能有問題,模仿Redis獲取slowlog的程式碼,寫了一個簡答的死迴圈,每次Sleep一秒,看看列印出來的差值是否正好1秒多點,如圖5所示:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖5

圖5的程式大概執行了20分鐘後,奇蹟出現了,gettimeofday果然有問題,下面是上面程式測試時間列印出來的LOG,如圖6:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖6

圖6中標紅的時間減去1秒等於1813ms,與slowlog時間如此相近!在容器所在的物理機上也測試一遍,發現有同樣的現象,排除因容器導致slowlog,希望的曙光似乎就在眼前了,那麼問題又來了:

1、到底為什麼會相差1800ms+呢?

2、為什麼第一批機器沒有這種現象呢?

3、為什麼之前跑在物理機上的Redis沒有這種現象呢?

帶著這三個問題,重新審視系統呼叫gettimeofday獲取當前時間背後的原理,發現一番新天地。

三、系統時鐘

系統時鐘的實現非常複雜,並且參考資料非常多。

簡單來說 我們可以透過

cat /sys/devices/system/clocksource/clocksource0/current_clocksource

命令來獲取當前系統的時鐘源,攜程的宿主機上都是統一Time Stamp Counter(TSC):80x86微處理器包括一個時鐘輸入插口,用來接收來自外部振盪器的時鐘訊號,從奔騰80x86微處理器開始,增加了一個計數器。

隨著每增加一個時鐘訊號而加一,透過rdtsc彙編指令也可以去讀TSC暫存器,這樣如果CPU的頻率是1GHz,TSC暫存器就能提供納秒級別的計時精度,並且現代CPU透過FLAG constant_tsc來保證即使CPU休眠也不影響TSC的頻率。

當選定TSC為時鐘源後,gettimeofday獲取牆上時鐘(wall-clock)正是從TSC暫存器讀出來的值轉換而來,所謂牆上時鐘主要是參照現實世界人們透過牆上時鐘獲取當前時間,但是用來計時並不準確,可能會被NTP或者管理員修改。

那麼問題又來了,宿主機的時間沒有被管理員修改,難道是被NTP修改?即使是NTP來同步,每次相差也不該有1800ms這麼久,它的意思是說難道宿主機的時鐘每次都在變慢然後被NTP拉回到正常時間?我們手工執行了下NTP同步,發現的確是有很大偏差,如圖7所示:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖7

按常識時鐘正常的物理機與NTP伺服器時鐘差異都在1ms以內,相差1s+絕對有問題,而且還是那個老問題,為什麼第一批次的機器上沒有問題?

四、核心BUG

兩個批次宿主機一樣的核心版本,第一批沒問題而第二批有問題,差異只可能在硬體上,非常有可能在計時上,翻看核心的commit log終於讓我們發現了這樣的commit,如圖8所示:

乾貨 | 攜程一次Redis遷移容器後Slowlog“異常”分析

圖8

該commit非常清楚指出,在4.9以後新增了一個宏定義INTEL_FAM6_SKYLAKE_X,但因為搞錯了該型別CPU的crystal frequency會導致該型別的CPU每10分鐘慢1秒鐘。

這時再看看我們的出問題的第二批宿主機xeon bronze 3104正好是skylake-x的伺服器,影響4.9-4.13的核心版本,宿主機核心4.10正好中招。

並且NTP每次同步間隔1024秒約慢1700ms,與slowlog異常完全吻合,而第一批次的機器CPU都不是SKYLAKE-X平臺的,避開了這個BUG,遷移之前Redis所在的物理機核心是3.10版本,自然也不存在這個問題。至此,終於解開上面三個疑惑。

五、總結

5.1 問題根因

透過上面的分析可以看出,問題根因在於核心4.9-4.13之間skylake-x平臺TSC晶振頻率的程式碼BUG,也就是說同時觸發這兩個因素都會導致系統時鐘變慢,疊加上Redis計時使用的gettimeofday會容易被NTP修改導致了本文開頭詭異的slowlog“異常”。有問題的宿主機核心升級到4.14版本後,時鐘變慢的BUG得到了修復。

5.2 怎麼獲取時鐘

對於應用需要打點記錄當前時間的場景,也就是說獲取Wall-Clock,可以使用clock_gettime傳入CLOCK_REALTIME引數,雖然gettimeofday也可以實現同樣的功能,但不建議繼續使用,因為在新的POSIX標準中該函式已經被廢棄。

對於應用需要記錄某個方法耗時的場景,必須使用clock_gettime傳入CLOCK_MONOTONIC引數,該引數獲得的是自系統開機起單調遞增的納秒級別精度時鐘,相比gettimeofday精度提高不少,並且不受NTP等外部服務影響,能準確更準確來統計耗時(java中對應的是System.nanoTime),也就是說所有使用gettimeofday來統計耗時(java中是System.currenttimemillis)的做法本質上都是錯誤的。

本文轉載自 | 攜程技術中心 

作者 | 李劍

微訊號 | ctriptech 

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

相關文章