乾貨 | 攜程容器偶發性超時問題案例分析（二）

2019 年 11 月 24 日
筆記

作者簡介

李劍，攜程系統研發部技術專家，負責Redis和Mongodb的容器化和服務化工作，喜歡深入分析系統疑難雜症。

周昕毅，攜程系統研發部雲平台高級研發經理。現負責攜程容器雲平台運維，Cloud Storage及Cloud Network基礎設施研發及運維。

本文為容器偶發性超時問題案例分析的第二篇，第一篇點這裡。

前言

隨著內核升級到4.14.67，看上去延遲的問題徹底解決了，然而並沒有，只是出現的更加緩慢。幾周後，超時報障又找了過來，我們用perf來分析，發現了一些異常。

如圖1所示是一個空負載的宿主機升級內核後8天的perf的數據，明顯可以看到kworker的max delay已經100ms+，而這次有規律的是，延遲比較大的都是最後四個核，對於12核的節點就是8-11，並且都是同一D廠的宿主機。而上篇中使用新內核後用來驗證解決問題的卻不是D廠的宿主機，也就是說除了內核，還有其他的因素導致了延遲。

圖1

NUMA和CPU親和性綁定

NUMA全稱Non-Uniform Memory Access，NUMA伺服器一般有多個節點，每個節點由多個CPU組成，並且具有獨立的本地記憶體，節點內部使用共有的記憶體控制器，節點之間是通過內部互聯（如QPI）進行通訊。

然而，訪問本地記憶體的速度遠遠高於訪問其他節點的遠地記憶體的速度，通常有幾十倍的性能差異，這也正是NUMA 名稱的由來。因為NUMA的這個特性，為了更好地發揮系統性能，應用程式應該盡量減少不同節點CPU之間的資訊交互。

無意中發現，D廠的機型與其他機型的NUMA配置不一樣。假設12核的機型，D廠的機型NUMA節點分配如下圖2所示：

圖2

而其他廠家的機型NUMA節點分配如下圖3所示：

圖3

為什麼會出現delay都是最後四個核上的進程呢？

經過深入排查才發現，原來相關同事之前為了讓k8s的相關進程和普通的用戶的進程相隔離，設置了CPU的親和性，讓k8s的相關進程綁定到宿主機的最後四個核上，用戶的進程綁定到其他的核上，但後面這一步並沒有生效。

還是拿12核的例子來說，上面的k8s是綁定到8-11核，但用戶的進程還是工作在0-11核上，更重要的是，最後4個核在遇到D廠家的這種機型時，實際上是跨NUMA綁定，導致了延遲越來越高，而用戶進程運行在相關的核上就會導致超時等各種故障。

確定問題後，解決起來就簡單了。將所有宿主機的綁核去掉，延遲就消失了，以下圖4是D廠的機型去掉綁核後開機26天perf的調度延遲，從數據上看一切都恢復正常。

圖4

新的問題

大約過了幾個月，又有新的超時問題找到我們。有了之前的排查經驗，我們覺得這次肯定能很輕易的定位到問題，然而現實無情地給予了我們當頭一棒，4.14.67內核的宿主機，還是有大量無規律超時。

深入分析

perf看調度延遲，如圖5所示，調度延遲比較大但並沒有集中在最後四個核上，完全無規律，同樣turbostat依然觀察到TSC的頻率在跳動。

圖5

在各種猜想和驗證都被一一證否後，我們開始挨個排除來做測試：

1、我們將某台A宿主機實例遷移走，perf看上去恢復了正常，而將實例遷移回來，延遲又出現了。

2、另外一台B宿主機上，我們發現即使將所有的實例都清空，perf依然能錄得比較高的延遲。

3、而與B相連編號同一機型的C宿主機遷移完實例後重啟，perf恢復正常。這時候看B的TOP，只有一個kubelet在消耗CPU，將這台宿主機上的kubelet停掉，perf正常，開啟kubelet後，問題又依舊。

這樣我們基本可以確定kubelet的某些行為導致了宿主機卡頓和實例超時，對比正常/非正常的宿主機kubelet日誌，每秒鐘都在獲取所有實例的監控資訊，在非正常的宿主機上，會列印以下的日誌。如圖6所示：

圖6

而在正常的宿主機上沒有該日誌或者該時間比較短，如圖7所示：

圖7

到這裡，我們懷疑這些LOG的行為可能指向了問題的根源。查看k8s程式碼，可以知道在獲取時間超過指定值longHousekeeping (100ms)後，k8s會記錄這一行為，而updateStats即獲取本地的一些監控數據，如圖8程式碼所示：

圖8

在網上搜索相關issue，問題指向cadvisor的消耗CPU過高，

https://github.com/kubernetes/kubernetes/issues/15644

https://github.com/google/cadvisor/issues/1498

而在某個issue中指出

（https://github.com/google/cadvisor/issues/1774），

echo2 > /proc/sys/vm/drop_caches

可以暫時解決這種問題。我們嘗試在有問題的機器上執行清除快取的指令，超時問題就消失了，如圖9所示。而從根本上解決這個問題，還是要減少取metrics的頻率，比較耗時的metrics乾脆不取或者完全隔離k8s的進程和用戶進程才可以。

圖9

硬體故障

在排查cadvisor導致的延遲的過程中，還發現一部分用戶報障的超時，並不是cadvisor導致的，主要表現在沒有Housekeeping的日誌，並且perf結果看上去完全正常，說明沒有調度方面的延遲，但從TSC的獲取上還是能觀察到異常。

由此我們懷疑這是另一種全新的故障，最重要的是我們將某台宿主機所有業務完全遷移掉，並關閉所有可以關閉的進程，只保留內核的進程後，TSC依然不正常並伴隨肉眼可見的卡頓，而這種現象跟之前DBA那台物理機卡頓的問題很相似，這告訴我們很有可能是硬體方面的問題。

從以往的排障經驗來看，TSC抖動程度對於我們排查宿主機是否穩定有重要的參考作用。這時我們決定將TSC的檢測程式做成一個系統服務，每100ms去取一次系統的TSC值，將TSC的差值大於指定值列印到日誌中，並採集單位時間的異常條目數和最大TSC差值，放在監控系統上，來觀察異常的規律。如圖10所示。

圖10

這樣採集有幾個好處：

1、程式消耗比較小，僅僅消耗幾個CPU cycles的時間，完全可以忽略不計；

2、對於正常的宿主機，該日誌始終為空；

3、對於有異常的宿主機，因為採集力度足夠小，可以很清晰地定位到異常的時間點，這樣對於宿主機偶爾抖動情況也能採集到；

恰好TSC檢測的服務上線不久，一次明顯的故障說明了它檢測宿主機是否穩定的有效性。如圖11，在某日8點多時，一台宿主機TSC突然升高，與應用的告警郵件和用戶報障同一時刻到來。如圖12所示：

圖11

圖12

將採集的日誌這樣展示後，我們一眼就發現問題都集中在某幾批次的同一廠商的宿主機上，並且我們找到之前DBA卡頓的物理機，也是這幾批次中的一台。我們收集了幾台宿主機的日誌詳情，回饋給廠商後，確認是硬體故障，無規律並且隨時可能觸發，需升級BIOS，如圖13廠商技術人員答覆的郵件所示，至此問題得到最終解決。

圖13

總結

本系列的兩篇文章基本上描述了我們遇到的容器偶發性超時問題分析的大部分過程，但排障過程遠比寫出來要艱難。

總的原則還是大膽假設，小心求證，設法找到無規律中的規律性，保持細緻耐心的鑽研精神，相信這些疑難雜症終會被一一解決。