調試Kubernetes集羣中的網絡停頓問題
我們曾經在這裏中聊起過Kubernetes ( Kubernetes at GitHub : https://github.blog/2017-08-16 ... ithub /)，在過去幾年，Kubernetes在Github已經成爲標準的部署模式。目前在Github，我們在Kubernetes上運行着海量的面向內部團隊以及面向C端的服務。
隨着Kubernetes集羣規模不斷增長，我們對於服務延遲的要求越來越嚴苛。我們開始觀察到一些運行在我們Kubernetes平臺上的服務正在面臨偶發的延遲問題，這些斷斷續續的問題並不是由於應用本身的性能問題導致的。
我們發現，Kubernetes集羣上的應用產生的延遲問題看上去似乎是隨機的，對於某些網絡連接的建立可能會超過100ms，從而使得下游的服務產生超時或者重試。這些服務本身處理業務的響應時間都能夠很好地保持在100ms以內，而建立連接就需要花費100ms以上對我們來說是不可忍受的。另外，我們也發現對於一些應該執行地非常快的SQL查詢（毫秒量級），從應用的角度看居然超過100ms，但是在MySQL數據庫的角度看又是完全正常的，並沒有發現可能出現的慢查詢問題。
通過排查，我們將問題縮小到與Kubernetes節點建立連接的這個環節，包括集羣內部的請求或者是涉及到外部的資源和外部的訪問者的請求。最簡單的重現這個問題的方法是：在任意的內部節點使用Vegeta ( https://github.com/tsenart/veget a) 對一個以 NodePort 暴露的服務發起 HTTP 壓測，我們就能觀察到不時會產生一些高延遲請求。在這篇文章中，我們將聊一聊我們是如何追蹤定位到這個問題的。
撥開迷霧找到問題的關鍵
我們想用一個簡單的例子來複現問題，那麼我們希望能夠把問題的範圍縮小，並移除不必要的複雜度。起初，數據在Vegeta和Kubernetes Pods之間的流轉的過程中涉及了太多的組件，很難確定這是不是一個更深層次的網絡問題，所以我們需要來做一個減法。
Vegeta客戶端會向集羣中的某個Kube節點發起TCP請求。在我們的數據中心的Kubernetes集羣使用Overlay網絡（運行在我們已有的數據中心網絡之上），會把Overlay網絡的IP包封裝在數據中心的IP包內。當請求抵達第一個kube節點，它會進行NAT轉換，從而把kube節點的IP和端口轉換成Overlay的網絡地址，具體來說就是運行着應用的Pod的IP和端口。再請求響應的時候，則會發生相應的逆變換（SNAT/DNAT）。這是一個非常複雜的系統，其中維持着大量可變的狀態，會隨着服務的部署而不斷更新。
在最開始利用Vegeta進行進行壓測的時候，我們發現在TCP握手的階段（SYN和SYN-ACK之間）存在延遲。爲了簡化HTTP和Vegeta帶來的複雜度，我們使用hping3來發送SYN包，並觀測響應的包是否存在延遲的情況，然後把連接關閉。我們能夠過濾出那些延遲超過100ms的包，來簡單地重現Vegeta的7層壓力測試或是模擬一個服務暴露在SYN攻擊中。以下的一段日誌顯示的是以10ms間隔向kube-node的30927端口發送TCP SYN/SYN-ACK包並過濾出慢請求的結果，
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms
根據日誌中的序列號以及時間，我們首先觀察到的是這種延遲並不是單次偶發的，而是經常聚集出現，就好像把積壓的請求最後一次性處理完似的。
接着，我們想要具體定位到是哪個組件有可能發生了異常。是kube-proxy的NAT規則嗎，畢竟它們有幾百行之多？還是IPIP隧道或類似的網絡組件的性能比較差？排查的一種方式是去測試系統中的每一個步驟。如果我們把NAT規則和防火牆邏輯刪除，僅僅使用IPIP隧道會發生什麼？
如果你同樣也在一個kube節點上，那麼Linux允許你直接和Pod進行通訊，非常簡單：
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms
從我們的結果看到，問題還是在那裏！這排除了iptables以及NAT的問題。那是不是TCP出了問題？我們來看下如果我們用ICMP請求會發生什麼，
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms
len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms
len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms
len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms
結果顯示ICMP仍然能夠復現問題。那是不是IPIP隧道導致了問題？讓我們來進一步簡化問題，
那麼有沒有可能這些節點之間任意的通訊都會帶來這個問題？
theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms
len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms
在這個複雜性的背後，簡單來說其實就是兩個kube節點之間的任何網絡通訊，包括ICMP。如果這個目標節點是“異常的”（某些節點會比另一些更糟糕，比如延遲更高，問題出現的頻率更高），那麼當問題發生時，我們仍然能看到類似的延遲。
那麼現在的問題是，我們顯然沒有在所有的機器上發現這個問題，爲什麼這個問題只出現在那些kube節點的服務器上？是在kube節點作爲請求發送方還是請求接收方時會出現呢？幸運的是，我們能夠輕易地把問題的範圍縮小：我們可以用一臺集羣外的機器作爲發送方，而使用相同的"已知故障"的機器作爲請求的目標。我們發現在這個方向上的請求仍然存在問題，
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms
然後重複以上操作，這次我們從kube節點發送請求到外部節點，
theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}\.'
^C
--- 172.16.33.44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms
通過查看抓包中的延遲數據, 我們獲得了更多的信息。具體來說，從發送端觀察到了延遲（下圖），然而接收端的服務器沒有看到延遲（上圖）-- 注意圖中的Delta列（單位是秒）:
另外，通過查看接收端的TCP以及ICMP網絡包的順序的區別 (基於序列ID)， 我們發現ICMP包總是按照他們發送的順序抵達接收端，但是送達時間不規律，而TCP包的序列ID有時會交錯，其中的一部分會停頓。尤其是，如果你去數SYN包發送/接收的端口，這些端口在接收端並不是順序的，而他們在發送端是有序的。
目前我們服務器所使用的網卡，比如我們在自己的數據中心裏面使用的那些硬件，在處理TCP和ICMP網絡報文時有一些微妙的區別。當一個數據報抵達的時候，網卡會對每個連接上傳遞的報文進行哈希，並且試圖將不同的連接分配給不同的接收隊列，併爲每個隊列 (大概) 分配一個CPU核心。對於TCP報文來說，這個哈希值同時包含了源IP、端口和目標IP、端口。換而言之，每個連接的哈希值都很有可能是不同的。對於ICMP包，哈希值僅包含源IP和目標IP，因爲沒有端口之說。這也就解釋了上面的那個發現。
另一個新的發現是一段時間內兩臺主機之間的ICMP包都發現了停頓，然而在同一段時間內TCP包卻沒有問題。這似乎在告訴我們，是接收的網卡隊列的哈希在"開玩笑"，我們幾乎確定停頓是發生在接收端處理RX包的過程中，而不是發送端的問題。
這排除了kube節點之間的傳輸問題，所以我們現在知道了這是在處理包的階段發生了停頓，並且是一些作爲接收端的kube節點。
深入挖掘 Linux 內核的網絡包處理過程
爲了理解爲什麼問題會出現在kube節點服務的接收端，我們來看下Linux是如何處理網絡包的。
在最簡單原始的實現中，網卡接收到一個網絡包以後會向Linux內核發送一箇中斷，告知有一個網絡包需要被處理。內核會停下它當前正在進行的其他工作，將上下文切換到中斷處理器，處理網絡報文然後再切換回到之前的工作任務。
上下文切換會非常慢，對於上世紀90年代10Mbit的網卡可能這個方式沒什麼問題，但現在許多服務器都是萬兆網卡，最大的包處理速度可能能夠達到1500萬包每秒：在一個小型的8核心服務器上這意味着每秒會產生數以百萬計的中斷。
許多年前，Linux新增了一個NAPI，Networking API用於代替過去的傳統方式，現代的網卡驅動使用這個新的API可以顯著提升高速率下包處理的性能。在低速率下，內核仍然按照如前所述的方式從網卡接受中斷。一旦有超過閾值的包抵達，內核便會禁用中斷，然後開始輪詢網卡，通過批處理的方式來抓取網絡包。這個過程是在"softirq"中完成的，或者也可以稱爲軟件中斷上下文(software interrupt context)。這發生在系統調用的最後階段，此時程序運行已經進入到內核空間，而不是在用戶空間。
這種方式比傳統的方式快得多，但也會帶來另一個問題。如果包的數量特別大，以至於我們將所有的CPU時間花費在處理從網卡中收到的包，但這樣我們就無法讓用戶態的程序去實際處理這些處於隊列中的網絡請求（比如從TCP連接中獲取數據等）。最終，隊列會堆滿，我們會開始丟棄包。爲了權衡用戶態和內核態運行的時間，內核會限制給定軟件中斷上下文處理包的數量，安排一個"預算"。一旦超過這個"預算"值，它會喚醒另一個線程，稱爲"ksoftiqrd"（或者你會在ps命令中看到過這個線程），它會在正常的系統調用路徑之外繼續處理這些軟件中斷上下文。這個線程會使用標準的進程調度器，從而能夠實現公平的調度。
通過整理Linux內核處理網絡包的路徑，我們發現這個處理過程確實有可能發生停頓。如果softirq處理調用之間的間隔變長，那麼網絡包就有可能處於網卡的RX隊列中一段時間。這有可能是由於CPU核心死鎖或是有一些處理較慢的任務阻塞了內核去處理softirqs。
將問題縮小到某個核心或者方法
到目前位置，我們相信這個延遲確實是有可能發生的，並且我們也知道我們似乎觀察到一些非常類似的跡象。下一步是需要確認這個理論，並嘗試去理解是什麼原因導致的問題。
讓我們再來看一下發生問題的網絡請求：
len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms
按照我們之前討論的，這些ICMP包會被散列到某一個特定的網卡RX隊列，然後被某個CPU核心處理。如果我們想要理解內核正在做什麼，那麼我們首先要知道到底是哪一個CPU核心以及softirq和ksoftiqrd是如何處理這些包的，這對我們定位問題會十分有幫助。
現在我們可以使用一些工具來幫助我們實時追蹤Linux內核的運行狀態，爲此我可以可以使用bcc。bcc允許你寫一小段C的程序，並掛載到內核的任意函數上，然後它可以把緩存事件並將其傳送給一個用戶態的Python程序，而這個Python程序對這些事件進行一些彙總分析然後把結果返回給你。以上所說的"掛載到內核的任意函數上"實際上是一個難點，但它已經儘可能地做到被安全使用，因爲它本身就是設計來爲了追蹤這類生產環境的問題，這些問題普遍無法簡單地在測試環境或者開發環境中重現。
我們的想法非常簡單：我們知道內核正在處理那些IMCP的Ping包，那麼我們就來攔截一下內核的icmp_echo方法，這個方法會接受一個入站方向的ICMP的"echo請求"包，併發起一個ICMP的回覆"echo response"。我們可以通過hping3中顯示的icmp_seq序列號來識別這些包。
這個bcc腳本的代碼看起來似乎很複雜，但將其分解以後聽起來並沒有那麼可怕。 icmp_echo函數傳遞了一個結構體的指針sk_buff * skb，它是包含ICMP echo請求的數據包。 我們可以做一些深入的研究，提取出echo.sequence（對應於上面hping3所示的icmp_seq），然後將其發送回用戶空間。 同時我們也可以方便地獲取到當前的進程名稱或是進程id。 當內核處理這些數據包時，我們能看到如下結果：
TGID PID PROCESS NAME ICMP_SEQ 0 0 swapper/11 770 0 0 swapper/11 771 0 0 swapper/11 772 0 0 swapper/11 773 0 0 swapper/11 774 20041 20086 prometheus 775 0 0 swapper/11 776 0 0 swapper/11 777 0 0 swapper/11 778 4512 4542 spokes-report-s 779
這裏關於進程名需要注意的是，在softirq這個發生在系統調用後的上下文中，你能看到發起這個系統調用的進程顯示爲"process"，即使這是內核在內核的上下文中處理它。
通過運行，我們現在可以將hping3觀察到的停頓數據包與處理它的進程相關聯。 對捕獲的icmp_seq值進行簡單grep操作，通過這些上下文能夠看出在處理這些數據包之前發生的情況。 符合以上hping3中顯示的icmp_seq值的數據包已被標記出來，同時也顯示了我們觀察到的rtt數值（括號內是我們假設RTT<50ms的請求沒有被過濾掉）：
TGID PID PROCESS NAME ICMP_SEQ ** RTT
10137 10436 cadvisor 1951
10137 10436 cadvisor 1952
76 76 ksoftirqd/11 1953 ** 99ms
76 76 ksoftirqd/11 1954 ** 89ms
76 76 ksoftirqd/11 1955 ** 79ms
76 76 ksoftirqd/11 1956 ** 69ms
76 76 ksoftirqd/11 1957 ** 59ms
76 76 ksoftirqd/11 1958 ** (49ms)
76 76 ksoftirqd/11 1959 ** (39ms)
76 76 ksoftirqd/11 1960 ** (29ms)
76 76 ksoftirqd/11 1961 ** (19ms)
76 76 ksoftirqd/11 1962 ** (9ms)
10137 10436 cadvisor 2068
10137 10436 cadvisor 2069
76 76 ksoftirqd/11 2070 ** 75ms
76 76 ksoftirqd/11 2071 ** 65ms
76 76 ksoftirqd/11 2072 ** 55ms
76 76 ksoftirqd/11 2073 ** (45ms)
76 76 ksoftirqd/11 2074 ** (35ms)
76 76 ksoftirqd/11 2075 ** (25ms)
76 76 ksoftirqd/11 2076 ** (15ms)
76 76 ksoftirqd/11 2077 ** (5ms)
以上的結果告訴我們一些事情。 首先，這些數據包由ksoftirqd/11進程處理的，它很方便地告訴我們這對特定的機器將其ICMP數據包散列到接收方的CPU核心11上。 我們還可以看到，每次看到停頓時，我們總是會看到在cadvisor的系統調用softirq上下文中處理了一些數據包，然後ksoftirqd接管並處理了積壓，而這恰好就對應於我們發現的那些停頓的數據包。
cadvisor始終在緊接卡頓的請求之前運行的事實也表明這可能與我們排查的問題相關。具有諷刺意味的是，正如cadvisor的主頁中描述的那樣，我們使用cadvisor正是爲了"分析正在運行的容器的資源使用情況和性能特徵"，但它卻引發了這一性能問題。與許多與容器相關的事情一樣，這些都是相對前沿的工具，是存在導致某些預想不到的性能下降的情況。
cadvisor做了什麼會導致停頓?
瞭解了停頓如何發生，導致停頓的進程以及發生停頓的CPU內核以後，我們現在對它有了一個很好的瞭解。爲了讓內核能夠硬阻塞而不是提前調度ksoftirqd，並且我們也看到了在cadvisor的softirq上下文中處理的數據包，我們認爲cadvisor調用syscall可能非常慢，而在它完成之後其餘的網絡包才能夠被正常處理：
這僅僅是一個理論，那我們如何驗證這是真實發生的呢？ 我們可以做的是跟蹤在整個過程中CPU內核上正在運行的內容，找出數據包超出"預算"並開始喚醒ksoftirqd處理的點，然後再回頭查看CPU核心上正在運行的內容。可以將其想象爲每隔幾毫秒對CPU進行一次X射線檢查。它看起來像這樣：
非常遍歷的是這個需求的大部分已經被實現。 perf record工具能以特定頻率對指定的CPU內核進行採樣，並且可以生成實時的調用圖（包括用戶空間和內核）。使用一個從Brendan Gregg開發的FlameGraph衍生的程序能夠對實時的調用進行記錄和操作，該工具保留了堆棧跟蹤的順序，我們可以每隔1ms採樣獲得單行堆棧跟蹤，然後獲得在ksoftirqd執行之前的100ms的樣本 ：
record 999 times a second, or every 1ms with some offset so not to align exactly with timers
sudo perf record -C 11 -g -F 999
take that recording and make a simpler stack trace.
sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100
結果如下，
(hundreds of traces that look similar) cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_r
日誌有很多，但細心的你可能已經發現了其中固定的模式：cadvisor然後ksoftirqd。那這意味着什麼？
其中每一行都是在某一時刻的追蹤記錄。每個調用的方法棧中的方法用分號來分割。在行的中間我們可以看到被調用的syscall是read(): ...; do_syscall_64;sys_read;... 所以cadvisor花費了大量的時間來調用read()系統調用，這個調用和mem_cgroup_*函數有關，因爲它是方法棧中處於棧底的方法）。
方法棧的追蹤並不能方便地顯示出read的具體內容，那麼我們可以使用strace來查看cadvisor到底在做什麼，並找到那些超過100ms的系統調用。
theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0\.[1-9]' [pid 10436] <... futex resumed> ) = 0 <0.156784> [pid 10432] <... futex resumed> ) = 0 <0.258285> [pid 10137] <... futex resumed> ) = 0 <0.678382> [pid 10384] <... futex resumed> ) = 0 <0.762328> [pid 10436] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 658 <0.179438> [pid 10384] <... futex resumed> ) = 0 <0.104614> [pid 10436] <... futex resumed> ) = 0 <0.175936> [pid 10436] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0.228091> [pid 10427] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 577 <0.207334> [pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113> [pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717> [pid 10436] <... read resumed> "cache 154234880\nrss 507904\nrss_h"..., 4096) = 660 <0.159891> [pid 10417] <... futex resumed> ) = 0 <0.917495> [pid 10436] <... futex resumed> ) = 0 <0.208172> [pid 10417] <... futex resumed> ) = 0 <0.190763> [pid 10417] <... read resumed> "cache 0\nrss 0\nrss_huge 0\nmapped_"..., 4096) = 576 <0.154442>
到這一步，我們非常確信read()系統調用是很慢的。從read讀取的內容和mem_cgroup這個上下文來看，那些read()調用是在讀取memory.state文件，這些文件用於描述系統的內存使用以及cgroup的限制。cadvisor通過輪詢這個文件來獲取容器所使用的資源的詳情。我們可以通過手動調用這個方法來驗證到底是內核還是cadvisor的問題：
theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null real 0m0.153s user 0m0.000s sys 0m0.152s theojulienne@kube-node-bad ~ $
由於我們可以重現它個問題，因此表明它是內核觸發了一個"病態"的方法。
是什麼導致這個讀取如此緩慢
那麼到了這個階段，我們可以很容易地查到其他人報告的類似的問題。 事實證明，這個問題早已被報告給cadvisor，這被發現是一個CPU使用率過高的問題，只是並沒有注意到延遲也會隨機地影響網絡棧。事實上，一些內部開發人員已經注意到cadvisor消耗的CPU超出了預期，但似乎沒有引起問題，因爲我們的服務器CPU性能充足，因此我們並沒有對CPU的使用情況進行調查。
縱觀這個問題，它主要是關於內存的cgroup，它負責管理與統計命名空間（容器）內的內存使用情況。當該cgroup中的所有進程退出時，內存cgroup會被Docker釋放。 但是，“內存”不僅是進程的內存，而且雖然進程內存的使用量已經消失，但事實證明，內核還爲緩存空間分配了內存，例如dentries和inode（目錄和文件元數據），這些內容被緩存到內存cgroup中。從這個問題可以看出：
”殭屍“cgroups：那些沒有進程運行並被刪除得cgroups仍然持有一定得內存空間（在我們的案例中，這些緩存對象是目錄數據，但也有可能是頁緩存或是tmpfs）。
與其在cgroup釋放的時候遍歷所有的緩存頁，而這也可能很慢，內核會惰性地等待這些內存需要用到的時候再去回收它們，當所有的內存頁被清理以後，相應的cgroup纔會最後被回收。與此同時，這些cgroup仍然會被計入統計信息中。
從性能的角度來看，他們通過分期回收每個頁面來攤銷直接整體回收的巨大耗時，選擇快速地進行初始的清理，但這種方式會保留一些緩存在內存中。但這也沒什麼問題，當內核回收緩存中的最後一頁內存時，cgroup最終會被清理，因此這並不是一個“泄漏”。 不幸的是，問題在於memory.stat執行搜索的方式，比如在我們的某些服務器上內核仍然是4.9版本，這個版本的實現是有問題的，再加上我們服務器一般都有大量的內存空間，這意味着最後一次內存緩存回收並清理殭屍cgroup可能要花很長時間。
事實證明，我們的節點具有大量的殭屍cgroup，有些節點的讀/停頓超過一秒鐘。
這個cadvisor問題的臨時解決方法是，立即釋放系統範圍內的目錄/inode節點緩存，這能夠立即消除讀取延遲，同時網絡延遲也得到解決，這是因爲緩存的刪除包括了那些”殭屍” cgroup佔用的緩存頁面，他們同時也被釋放了。這並不是最終的解決方案，但可以驗證問題的原因。
事實證明，較新的內核版本（4.19+）改進了memory.stat調用的性能，因此在更新到這個版本的內核以後這不再是一個問題。 在此期間，我們使用現有的工具來檢測Kubernetes集羣中節點出現的問題並優雅地移除並重新啓動它們：我們正是利用這些工具來檢測延遲的情況，當發現延遲高到會觸發問題的時候，我們隨即會通過正常重新啓動來對其進行處理 。這爲我們提供了喘息的機會，再次期間我們能夠升級剩餘的服務器的系統和內核。
總結一下
由於此問題表現爲NIC RX隊列停頓幾百毫秒，它導致了短連接上的高延遲以及在連接中間（例如MySQL查詢和響應數據包之間）出現的延遲。理解和維護我們最基礎的系統（如Kubernetes）的性能對於在其之上構建的所有服務的可靠性和速度都至關重要。 當我們爲此作出大量的技術"投資"並提高性能時，我們運行的每個系統都會從這些改進中受益。
![[譯] 總記不住 Helm 和 kubectl 命令？這場超市購物之旅可以幫你](https://img2.tuicool.com/mQvEJnB.png!web)
