如何除錯Kubernetes叢集中的網路延遲問題

語言: CN / TW / HK

本文深入研究和解決了 Kubernetes 平臺上的服務零星延遲問題,就在不久前我也遇到了類似的問題,看似是玄學事件,剛開始歸結於網路鏈路抖動,一段時間後依然存在,雖然影響都是 P99.99 以後的資料,但是擾人心智,最後通過多方面定位,解決了該問題。最後發現跟業務、網路都沒有什麼關係,而是基礎設施自身出了問題,如下文給了一個具體排查方案,並從一定程度上解釋了容器、cgroup、CPU 會給網路延遲帶來怎樣的影響。

隨著 Kubernetes 叢集規模不斷增長,我們對於服務延遲的要求越來越嚴苛。我們開始觀察到一些執行在我們 Kubernetes 平臺上的服務正在面臨偶發的延遲問題,這些斷斷續續的問題並不是由於應用本身的效能問題導致的。

我們發現,Kubernetes 叢集上的應用產生的延遲問題看上去似乎是隨機的,對於某些網路連線的建立可能會超過 100ms,從而使得下游的服務產生超時或者重試。這些服務本身處理業務的響應時間都能夠很好地保持在 100ms 以內,而建立連線就需要花費 100ms 以上對我們來說是不可忍受的。另外,我們也發現對於一些應該執行非常快的 SQL 查詢(毫秒量級),從應用的角度看居然超過 100ms,但是在 MySQL 資料庫的角度看又是完全正常的,並沒有發現可能出現的慢查詢問題。

通過排查,我們將問題縮小到與 Kubernetes 節點建立連線的這個環節,包括叢集內部的請求或者是涉及到外部的資源和外部的訪問者的請求。最簡單的重現這個問題的方法是:在任意的內部節點使用 Vegeta 對一個以 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 包並過濾出慢請求的結果,

[email protected] ~ $ 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 進行通訊,非常簡單:

[email protected] ~ $ 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 請求會發生什麼。

[email protected] ~ $ 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 隧道導致了問題?讓我們來進一步簡化問題。

那麼有沒有可能這些節點之間任意的通訊都會帶來這個問題?

[email protected] ~ $ 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 節點作為請求傳送方還是請求接收方時會出現呢?幸運的是,我們能夠輕易地把問題的範圍縮小:我們可以用一臺叢集外的機器作為傳送方,而使用相同的“已知故障”的機器作為請求的目標。我們發現在這個方向上的請求仍然存在問題。

[email protected] ~ $ 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 節點發送請求到外部節點。

[email protected] ~ $ 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 的系統呼叫。

[email protected] ~ $ 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 的問題:

[email protected] ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null

real    0m0.153s
user    0m0.000s
sys    0m0.152s
[email protected] ~ $

由於我們可以重現它個問題,因此表明它是核心觸發了一個“病態”的方法。

是什麼導致這個讀取如此緩慢

那麼到了這個階段,我們可以很容易地查到其他人報告的類似的問題。事實證明,這個問題早已被報告給 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)的效能對於在其之上構建的所有服務的可靠性和速度都至關重要。當我們為此作出大量的技術"投資"並提高效能時,我們執行的每個系統都會從這些改進中受益。

原文連結: http://github.blog/2019-11-21-debugging-network-stalls-on-kubernetes/

推薦

故障排除的思路及見解

K8S常見故障及解決方法

隨手關注或者”在看“,誠摯感謝!