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

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

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

一、問題描述 

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

圖 1

二、分析過程 

2.1 什么是Slowlog

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

圖 2 

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

2.2 矛盾的日志

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

圖 3 

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

圖 4 

2.3 求助社區(qū)

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

很快社區(qū)有人回復(fù)，可能是NUMA架構(gòu)導(dǎo)致的問題，但也同時(shí)表示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 豁然開朗

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

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

圖 5 

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

圖 6 

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

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

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

三、系統(tǒng)時(shí)鐘 

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

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

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

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

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

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

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

圖 7

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

四、內(nèi)核BUG 

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

圖 8

該commit非常清楚指出，在4.9以后添加了一個(gè)宏定義INTEL_FAM6_SKYLAKE_X，但因?yàn)楦沐e(cuò)了該類型CPU的crystal frequency會(huì)導(dǎo)致該類型的CPU每10分鐘慢1秒鐘。

這時(shí)再看看我們的出問題的第二批宿主機(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平臺(tái)的，避開了這個(gè)BUG，遷移之前Redis所在的物理機(jī)內(nèi)核是3.10版本，自然也不存在這個(gè)問題。至此，終于解開上面三個(gè)疑惑。

五、總結(jié) 

5.1 問題根因

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

5.2 怎么獲取時(shí)鐘

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

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