前言
問題描述某一天接到使用者報障說，Redis叢集有超時現象發生，比較頻繁，而訪問的QPS也比較低。緊接著，陸續有其他使用者也報障Redis訪問超時。在這些報障容器所在的宿主機裡面，我們猛然發現有之前因為時鐘漂移問題升級過核心到4.14.26的宿主機ServerA，心裡突然有一絲不詳的預感。
初步分析因為現代軟體部署結構的複雜性以及網路的不可靠性，我們很難快速定位“connect timout”或“connectreset by peer”之類問題的根因。
歷史經驗告訴我們，一般比較大範圍的超時問題要麼和交換機路由器之類的網路裝置有關，要麼就是底層系統不穩定導致的故障。從報障的情況來看，4.10和4.14的核心都有，而宿主機的機型也涉及到多個批次不同廠家，看上去沒頭緒，既然沒什麼好辦法，那就抓個包看看吧。
圖1
圖2
圖1是App端容器和宿主機的抓包，圖2是Redis端容器和宿主機的抓包。因為APP和Redis都部署在容器裡面（圖3），所以一個完整請求的包是B->A->C->D，而Redis的回包是D->C->A->B。
圖3
上面抓包的某一條請求如下：
1）B(圖1第二個)的請求時間是21:25:04.846750 #99
2）到達A(圖1第一個)的時間是21:25:04.846764 #96
3）到達C(圖2第一個)的時間是21:25:07.432436 #103
4）到達D(圖2第二個)的時間是21:25:07.432446 #115
該請求從D回覆如下：
1）D的回覆時間是21:25:07.433248 #116
2）到達C的時間是21:25:07.433257 #104
3）到達A點時間是21:25:05:901108 #121
4）到達B的時間是21:25:05:901114 #124
從這一條請求的訪問鏈路我們可以發現，B在200ms超時後等不到回包。在21：25:05.055341重傳了該包#100，並且可以從C收到重傳包的時間#105看出，幾乎與#103的請求包同時到達，也就是說該第一次的請求包在網路上被延遲傳輸了。大致的示意如下圖4所示：
圖4
從抓包分析來看，宿主機上好像並沒有什麼問題，故障在網路上。而我們同時在兩邊宿主機，容器裡以及連線宿主機的交換機抓包，就變成了下面圖5所示，假設連線A的交換機為E，也就是說A->E這段的網路有問題。
圖5
陷入僵局儘管發現A->E這段有問題，排查卻也就此陷入了僵局，因為影響的宿主機遍佈多個IDC，這也讓我們排除了網路裝置的問題。我們懷疑是否跟宿主機的某些TCP引數有關，比如TSO/GSO，一番測試後發現開啟關閉TSO/GSO和修改核心引數對解決問題無效，但同時我們也觀察到，從相同IDC裡任選一臺宿主機Ping有問題的宿主機，百分之幾的概率看到很高的響應值，如下圖6所示：
圖6
同一個IDC內如此高的Ping響應延遲，很不正常。而這時DBA告訴我們，他們的某臺物理機ServerB也有類似的的問題，Ping延遲很大，SSH上去後明顯感覺到有卡頓，這無疑給我們解決問題帶來了希望，但又更加迷惑：
1）延遲好像跟核心版本沒有關係，3.10，4.10，4.14的三個版本核心看上去都有這種問題。
2）延遲和容器無關，因為延遲都在宿主機上到連線宿主機的交換機上發現的。
3）ServerB跟ServerA雖然表現一樣，但細節上看有區別，我們的宿主機在重啟後基本上都能恢復一段時間後再復現延遲，但ServerB重啟也無效。
由此我們判斷ServerA和ServerB的症狀並不是同一個問題，並讓ServerB先升級韌體看看。在升級韌體後ServerB恢復了正常，那麼我們的宿主機是不是也可以靠升級韌體修復呢？答案是並沒有。升級韌體後沒過幾天，延遲的問題又出現了。
意外發現回過頭來看之前為了排查Skylake時鐘漂移問題的ServerA，上面一直有個簡單的程式在執行，來統計時間漂移的值，將時間差記到檔案中。當時這個程式是為了驗證時鐘漂移問題是否修復，如圖7：
圖7
這個程式跑在宿主機上，每個機器各有差異，但正常的時間差應該是100us以內，但1個多月後，時間差異越來越大，如圖8，最大能達到幾百毫秒以上。這告訴我們可能通過這無意中的log來找到根因，而且驗證了上面3的這個猜想，宿主機是執行一段時間後逐漸出問題，表現為第一次打點到第二次打點之間，排程會自動delay第二次打點。
圖8
TSC和PerfTurbostat是intel開發的，用來檢視CPU狀態以及睿頻的工具，同樣可以用來檢視TSC的頻率。而關於TSC，之前的文章 《攜程一次Redis遷移容器後Slowlog“異常”分析》 中有過相關介紹，這裡就不再展開。
在有問題的宿主機上，TSC並不是恆定的，如圖9所示，這個跟相關資料有出入，當然我們分析更可能的原因是，turbostat兩次去取TSC的時候，被核心排程delay了，如果第一次取時被delay導致取的結果比實際TSC的值要小，而如果第二次取時被delay會導致取的結果比實際值要大。
圖9
Perf 是內置於Linux上的基於取樣的效能分析工具，一般隨著核心一起編譯出來，具體的用法可以搜尋相關資料，這裡也不展開。用perf sched record -a sleep 60和perf sched latency -s max來檢視linux的排程延遲，發現最大能錄得超過1s的延遲，如圖10和圖11所示。使用者態的程序有時因為CPU隔離和程式碼問題導致比較大的延遲還好理解，但這些程序都是核心態的。儘管linux的CFS排程並非實時的排程，但在負載很低的情況下超過1s的排程延遲也是匪夷所思的。
圖10
圖11
根據之前的打點資訊和turbostat以及perf的資料，我們非常有理由懷疑是核心的排程有問題，這樣我們就用基於rdtscp指令更精準地來獲取TSC值來檢測CPU是否卡頓。rdtscp指令不僅可以獲得當前TSC的值，並且可以得到對應的CPU ID。如圖12所示：
圖12
上面的程式編譯後，放在宿主機上依次綁核執行，我們發現在問題的宿主機上可以打印出比較大的TSC的值。每間隔100ms去取TSC的值，將獲得的相減，在正常的宿主機上它的值應該跟CPU的TSC緊密相關，比如我們的宿主機上TSC是1.7GHZ的頻率，那麼0.1s它的累加值應該是170000000，正常獲得的值應該是比170000000多一點，圖13的第五條的值本身就說明了該宿主機的排程延遲在2s以上。
圖13
真相大白通過上面的檢測手段，可以比較輕鬆地定位問題所在，但還是找不到根本原因。這時我們突然想起來，線上Redis大規模使用宿主機的核心4.14.67並沒有類似的延遲，因此我們懷疑這種延遲問題是在4.14.26到4.14.67之間的bugfix修復掉了。
檢視commit記錄，先二分查詢大版本，再將懷疑的點單獨拎出來patch測試，終於發現了這個4.14.36-4.14.37之間的（圖14）commit:
https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?h=v4.14.37&id=b8d4055372b58aad4a51b67e176eabdcc238fde3
圖14
從該commit的內容來看，修復了無效的apic id會導致possible CPU個數不正確的情況，那麼什麼是x2apic呢？什麼又是possible CPU？怎麼就導致了排程的延遲呢？
說到x2apic，就必須先知道apic, 翻查網上的資料就發現，apic全稱Local Advanced ProgrammableInterrupt Controller，是一種負責接收和傳送中斷的晶片，整合在CPU內部，每個CPU有一個屬於自己的local apic。它們通過apic id進行區分。而x2apic是apic的增強版本，將apic id擴充到32位，理論上支援2^32-1個CPU。簡單的說，作業系統通過apic id來確定CPU的個數。
而possible CPU則是核心為了支援CPU熱插拔特性，在開機時一次載入，相應的就有online，offline CPU等，通過修改/sys/devices/system/cpu/cpu9/online可以動態關閉或開啟一個CPU，但所有的CPU個數就是possible CPU，後續不再修改。
該commit指出，因為沒有忽略apic id為0xffffffff的值，導致possible CPU不正確。此commit看上去跟我們的延遲問題找不到關聯，我們也曾向該issue的提交者請教排程延遲的問題，對方也不清楚，只是表示在自己環境只能復現possible CPU增加4倍，vmstat的執行時間增加16倍。
這時我們檢視有問題的宿主機CPU資訊，奇怪的事情發生了，如圖15所示，12核的機器上possbile CPU居然是235個，而其中12-235個是offline狀態，也就是說真正工作的只有12個，這麼說好像還是跟延遲沒有關係。
圖15
繼續深入研究possbile CPU，我們發現了一些端倪。從核心程式碼來看，引用for_each_possible_cpu()這個函式的有600多處，遍佈各個核心子模組，其中關鍵的核心模組比如vmstat，shed,以及loadavg等都有對它的大量呼叫。而這個函式的邏輯也很簡單，就是遍歷所有的possible CPU，那麼對於12核的機器，它的執行時間是正常宿主機執行時間的將近20倍！該commit的作者也指出太多的CPU會浪費向量空間並導致BUG（https://lkml.org/lkml/2018/5/2/115），而BUG就是排程系統的緩慢延遲。
以下圖16，圖17是對相同機型相同廠商的兩臺空負載宿主機的kubelet的perf資料（perf stat -p $pid sleep 60），圖16是uptime 2天的，而圖17是uptime 89天的。
圖16
圖17
我們一眼就看出圖16的宿主機不正常，因為無論是CPU的消耗，上下文的切換速度，指令週期，都遠劣於圖17的宿主機，並且還在持續惡化，這就是宿主機延遲的根本原因。而圖17宿主機恰恰只是圖16的宿主機打上圖14的patch後的核心，可以看到，possible CPU恢復正常(圖18)，至此超時問題的排查告一段落。
圖18
總結我們排查發現，不是所有的宿主機，所有的核心都在此BUG的影響範圍內，具體來說4.10（之前的有可能會有影響，但我們沒有類似的核心，無法測試）-4.14.37（因為是stable分支，所以master分支可能更靠後）的核心，CPU為skylake及以後型號的某些廠商的機型會觸發這個BUG。
確認是否受影響也比較簡單，檢視possible CPU是否是真實CPU即可。