容器化對于Redis自動化運維效率、資源利用率方面都有巨大提升，攜程在對Redis在容器上性能和穩(wěn)定性進(jìn)行充分驗證后，啟動了生產(chǎn)Redis遷移容器化的項目。其中第一批次兩臺宿主機(jī)，第二批次五臺宿主機(jī)。

本次“異常”是第二批次遷移過程中發(fā)現(xiàn)的，排查過程一波三折，最終得出讓人吃驚的結(jié)論。

希望本次結(jié)論能給遇到同樣問題的小伙伴以啟發(fā)，另外本次分析問題的思路對于分析其他疑難雜癥也有一定借鑒作用。

一、問題描述 

在某次Redis遷移容器后，DBA發(fā)來告警郵件，slowlog>500ms，同時在DBA的慢日志查詢里可以看到有1800ms左右的日志，如下圖1所示：  

圖 1

二、分析過程 

2.1 什么是Slowlog

在分析問題之前，先簡單解釋下Redis的slowlog。閱讀Redis源碼(圖2)不難發(fā)現(xiàn)，當(dāng)某次Redis的操作大于配置中slowlog-log-slower-than設(shè)置的值時，Redis就會將該值記錄到內(nèi)存中，通過slowlog get可以獲取該次slowlog發(fā)生的時間和耗時，圖1的監(jiān)控數(shù)據(jù)也是從此獲得。 

圖 2 

也就是說，slowlog只是單純的計算Redis執(zhí)行的耗時時間，與其他因素如網(wǎng)絡(luò)之類的都沒關(guān)系。

2.2 矛盾的日志

每次slowlog都是1800+ms并且都隨機(jī)出現(xiàn)，在第一批次Redis容器化的宿主機(jī)上完全沒有這種現(xiàn)象，而QPS遠(yuǎn)小于第一批次遷移的某些集群，按常理很難解釋，這時候翻看CAT記錄，更加加重了我們的疑惑，見圖3： 

圖 3 

CAT是攜程根據(jù)開源軟件(https://github.com/dianping/cat)的定制版本，用于客戶端記錄打點的耗時，從圖中可以很清晰的看到，Redis打點的最大值367ms也遠(yuǎn)小于1800ms，它等于是說下面這張自相矛盾圖，見圖4： 

圖 4 

2.3 求助社區(qū)

所以說，slowlog問題要么是CAT誤報，要么是Redis誤報，但Redis使用如此廣泛，并且經(jīng)過詢問CAT的維護(hù)者說CAT有一定的消息丟棄率，而Redis在官方github issue中并沒有發(fā)現(xiàn)類似的slowlog情形，因此我們第一感覺是CAT誤報，并在官方Redis issue中提問，試圖獲取社區(qū)的幫助。

很快社區(qū)有人回復(fù)，可能是NUMA架構(gòu)導(dǎo)致的問題，但也同時表示NUMA導(dǎo)致slowlog高達(dá)1800ms很不可思議。關(guān)于NUMA的資料網(wǎng)上有很多，這里不再贅述，我們在查閱相關(guān)NUMA資料后也發(fā)現(xiàn)，NUMA架構(gòu)導(dǎo)致如此大的slowlog不太可能，因此放棄了這條路徑的嘗試。

2.4 豁然開朗

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

重新閱讀Redis源代碼，直覺發(fā)現(xiàn)gettimeofday()可能有問題，模仿Redis獲取slowlog的代碼，寫了一個簡答的死循環(huán)，每次Sleep一秒，看看打印出來的差值是否正好1秒多點，如圖5所示： 

圖 5 

圖5的程序大概運行了20分鐘后，奇跡出現(xiàn)了，gettimeofday果然有問題，下面是上面程序測試時間打印出來的LOG，如圖6： 

圖 6 

圖6中標(biāo)紅的時間減去1秒等于1813ms，與slowlog時間如此相近!在容器所在的物理機(jī)上也測試一遍，發(fā)現(xiàn)有同樣的現(xiàn)象，排除因容器導(dǎo)致slowlog，希望的曙光似乎就在眼前了，那么問題又來了：

1. 到底為什么會相差1800ms+呢?
2. 為什么第一批機(jī)器沒有這種現(xiàn)象呢?
3. 為什么之前跑在物理機(jī)上的Redis沒有這種現(xiàn)象呢?

帶著這三個問題，重新審視系統(tǒng)調(diào)用gettimeofday獲取當(dāng)前時間背后的原理，發(fā)現(xiàn)一番新天地。

三、系統(tǒng)時鐘 

系統(tǒng)時鐘的實現(xiàn)非常復(fù)雜，并且參考資料非常多。

簡單來說 我們可以通過命令：

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

來獲取當(dāng)前系統(tǒng)的時鐘源，攜程的宿主機(jī)上都是統(tǒng)一Time Stamp Counter(TSC)：80x86微處理器包括一個時鐘輸入插口，用來接收來自外部振蕩器的時鐘信號，從奔騰80x86微處理器開始，增加了一個計數(shù)器。

隨著每增加一個時鐘信號而加一，通過rdtsc匯編指令也可以去讀TSC寄存器，這樣如果CPU的頻率是1GHz，TSC寄存器就能提供納秒級別的計時精度，并且現(xiàn)代CPU通過FLAG constant_tsc來保證即使CPU休眠也不影響TSC的頻率。

當(dāng)選定TSC為時鐘源后，gettimeofday獲取墻上時鐘(wall-clock)正是從TSC寄存器讀出來的值轉(zhuǎn)換而來，所謂墻上時鐘主要是參照現(xiàn)實世界人們通過墻上時鐘獲取當(dāng)前時間，但是用來計時并不準(zhǔn)確，可能會被NTP或者管理員修改。

那么問題又來了，宿主機(jī)的時間沒有被管理員修改，難道是被NTP修改?即使是NTP來同步，每次相差也不該有1800ms這么久，它的意思是說難道宿主機(jī)的時鐘每次都在變慢然后被NTP拉回到正常時間?我們手工執(zhí)行了下NTP同步，發(fā)現(xiàn)的確是有很大偏差，如圖7所示：  

圖 7

按常識時鐘正常的物理機(jī)與NTP服務(wù)器時鐘差異都在1ms以內(nèi)，相差1s+絕對有問題，而且還是那個老問題，為什么第一批次的機(jī)器上沒有問題?

四、內(nèi)核BUG 

兩個批次宿主機(jī)一樣的內(nèi)核版本，第一批沒問題而第二批有問題，差異只可能在硬件上，非常有可能在計時上，翻看內(nèi)核的commit log終于讓我們發(fā)現(xiàn)了這樣的commit，如圖8所示： 

圖 8

該commit非常清楚指出，在4.9以后添加了一個宏定義INTEL_FAM6_SKYLAKE_X，但因為搞錯了該類型CPU的crystal frequency會導(dǎo)致該類型的CPU每10分鐘慢1秒鐘。

這時再看看我們的出問題的第二批宿主機(jī)xeon bronze 3104正好是skylake-x的服務(wù)器，影響4.9-4.13的內(nèi)核版本，宿主機(jī)內(nèi)核4.10正好中招。

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

五、總結(jié) 

5.1 問題根因

通過上面的分析可以看出，問題根因在于內(nèi)核4.9-4.13之間skylake-x平臺TSC晶振頻率的代碼BUG，也就是說同時觸發(fā)這兩個因素都會導(dǎo)致系統(tǒng)時鐘變慢，疊加上Redis計時使用的gettimeofday會容易被NTP修改導(dǎo)致了本文開頭詭異的slowlog“異常”。有問題的宿主機(jī)內(nèi)核升級到4.14版本后，時鐘變慢的BUG得到了修復(fù)。

5.2 怎么獲取時鐘

對于應(yīng)用需要打點記錄當(dāng)前時間的場景，也就是說獲取Wall-Clock，可以使用clock_gettime傳入CLOCK_REALTIME參數(shù)，雖然gettimeofday也可以實現(xiàn)同樣的功能，但不建議繼續(xù)使用，因為在新的POSIX標(biāo)準(zhǔn)中該函數(shù)已經(jīng)被廢棄。

對于應(yīng)用需要記錄某個方法耗時的場景，必須使用clock_gettime傳入CLOCK_MONOTONIC參數(shù)，該參數(shù)獲得的是自系統(tǒng)開機(jī)起單調(diào)遞增的納秒級別精度時鐘，相比gettimeofday精度提高不少，并且不受NTP等外部服務(wù)影響，能更準(zhǔn)確來統(tǒng)計耗時(Java中對應(yīng)的是System.nanoTime)，也就是說所有使用gettimeofday來統(tǒng)計耗時(Java中是System.currenttimemillis)的做法本質(zhì)上都是錯誤的。