乾貨 | 攜程一次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是攜程根據開源軟體()的定製版本,用於客戶端記錄打點的耗時,從圖中可以很清晰的看到,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)的做法本質上都是錯誤的。
本文轉載自 | 攜程技術中心
作者 | 李劍
微訊號 | ctriptech
來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/31545808/viewspace-2285239/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- 乾貨 | 攜程圖片服務架構架構
- 乾貨 | 攜程線上風控系統架構架構
- 乾貨 | 攜程日誌系統治理演進之路
- 攜程MySQL遷移OceanBase最佳實踐|分享MySql
- 乾貨:Bitmap 複用時的一個異常
- 今晚遷移資料庫異常順利資料庫
- 乾貨 | 攜程酒店實時數倉架構和案例架構
- 記一次Blog遷移到Ghost(內含乾貨)
- 一次VPN隧道建立異常分析
- 科普乾貨IT知識,Java的常見異常有哪些?Java
- 記一次 GitLab 的遷移過程Gitlab
- 一次網站遷移故障及分析網站
- Redis鍵遷移Redis
- 【Redis】 redis資料遷移Redis
- 跨越異構鴻溝,Redis 遷移同步過程中的挑戰與解決方案Redis
- 一次透過dump檔案分析OutOfMemoryError異常程式碼定位過程Error
- 線上redis服務記憶體異常分析。Redis記憶體
- 乾貨 | 攜程酒店基於血緣後設資料的資料流程最佳化實踐
- 一次分割槽查詢異常的分析
- 乾貨 | 攜程酒店排序推薦廣告高效可靠資料基座--填充引擎排序
- 線上redis遷移思路Redis
- redis資料遷移Redis
- 【Redis】redis遷移資料到redis-clusterRedis
- 一次資料庫異常的處理過程資料庫
- 用Rman 異機遷移
- 乾貨好文 | 初探MySQL遷移到ClickHouseMySql
- 乾貨 | 資料為王,攜程國際火車票的 ShardingSphere 之路
- docker 容器操作、應用部署、mysql,redis,nginx、遷移與備份、DockerfileDockerMySqlRedisNginx
- redis原始碼學習之slowlogRedis原始碼
- 3分鐘短文:一看就是乾貨!Laravel遷移資料庫!Laravel資料庫
- redis資料庫遷移Redis資料庫
- expdp的一次遷移
- 一次線上Redis類轉換異常排查引發的思考Redis
- 故障分析 | MySQL 遷移後 timestamp 列 cannot be nullMySqlNull
- Flutter 常見異常分析Flutter
- MySQL儲存過程-->通過遊標遍歷和異常處理遷移資料到歷史表MySql儲存過程
- 【PyTHON】redis資料遷移PythonRedis
- 記錄一次Flink作業異常的排查過程