攜程一次 Redis 遷移容器後 Slowlog “異常” 分析
作者簡介
李劍，攜程技術保障中心繫統研發部資深軟體工程師，負責Redis和Mysql的容器化和服務化工作，以及維護容器宿主機的核心版本，喜歡深入分析系統疑難雜症。
容器化對於Redis自動化運維效率、資源利用率方面都有巨大提升，攜程在對Redis在容器上效能和穩定性進行充分驗證後，啟動了生產Redis遷移容器化的專案。其中第一批次兩臺宿主機，第二批次五臺宿主機。
本次“異常”是第二批次遷移過程中發現的，排查過程一波三折，最終得出 讓人吃驚 的結論。
希望本次結論能給遇到同樣問題的小夥伴以啟發，另外本次分析問題的思路對於分析其他疑難雜症也有一定借鑑作用。
一、問題描述
在某次Redis遷移容器後，DBA發來告警郵件，slowlog>500ms，同時在DBA的慢日誌查詢裡可以看到有1800ms左右的日誌，如下圖1所示：
圖1
二、分析過程
2.1 什麼是slowlog
在分析問題之前，先簡單解釋下Redis的slowlog。閱讀Redis原始碼（圖2）不難發現，當某次Redis的操作大於配置中 slowlog -log-slower-than 設定的值時，Redis就會將該值記錄到記憶體中，通過slowlog get可以獲取該次slowlog發生的時間和耗時，圖1的監控資料也是從此獲得。
圖2
也就是說，slowlog只是單純的計算Redis執行的耗時時間，與其他因素如網路之類的都沒關係。
2.2 矛盾的日誌
每次slowlog都是1800+ms並且都隨機出現，在第一批次Redis容器化的宿主機上完全沒有這種現象，而QPS遠小於第一批次遷移的某些叢集，按常理很難解釋，這時候翻看CAT記錄，更加加重了我們的疑惑，見圖3：
圖3
CAT是攜程根據開源軟體(https://github.com/dianping/cat)的定製版本，用於客戶端記錄打點的耗時，從圖中可以很清晰的看到，Redis打點的最大值367ms也遠小於1800ms，它等於是說下面這張自相矛盾圖，見圖4：
圖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所示：
圖5
圖5的程式大概運行了20分鐘後，奇蹟出現了，gettimeofday果然有問題，下面是上面程式測試時間打印出來的LOG，如圖6：
圖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所示：
圖7
按常識時鐘正常的物理機與NTP伺服器時鐘差異都在1ms以內，相差1s+絕對有問題，而且還是那個老問題，為什麼第一批次的機器上沒有問題？
四、核心BUG
兩個批次宿主機一樣的核心版本，第一批沒問題而第二批有問題，差異只可能在硬體上，非常有可能在計時上，翻看核心的commit log終於讓我們發現了這樣的commit，如圖8所示：
圖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）的做法本質上都是錯誤的。
【推薦閱讀】
11月23日上海，
攜程首屆技術峰會，
公眾號粉絲購票平臺輸入優惠碼“ F180 ”
可180元購票（原價280元）
戳“閱讀原文”直達~
