Kubernetes クラスターのネットワーク遅延問題をデバッグする方法

少し前に、同様の問題に遭遇しました。それは形而上学的な出来事のように思えました。当初、これはネットワーク リンク ジッターに起因するものと考えられていました。それはしばらく経ってもまだ存在していました。 P99.99以降のデータに影響があったとはいえ、不安でした。最終的に、多面的なポジショニングによって問題は解決されました。最終的に、問題はビジネスやネットワークとは関係なく、インフラストラクチャ自体に問題があることがわかりました。次の記事では、具体的なトラブルシューティング プランを示し、コンテナー、cgroup、CPU がネットワーク遅延にどのように影響するかをある程度説明します。

Kubernetes クラスターの規模が拡大し続けるにつれて、サービス レイテンシに対する要件はますます厳しくなります。私たちの Kubernetes プラットフォーム上で実行されている一部のサービスで、時折レイテンシの問題が発生していることに気づき始めました。これらの断続的な問題は、アプリケーション自体のパフォーマンスの問題によって発生したものではありません。

Kubernetes クラスター上のアプリケーションによって生成されるレイテンシの問題はランダムであるようで、一部のネットワーク接続の確立に 100 ミリ秒を超える可能性があり、ダウンストリーム サービスがタイムアウトまたは再試行する原因となることがわかりました。これらのサービス自体の業務処理における応答時間は 100 ミリ秒以内に抑えることができますが、接続を確立するには 100 ミリ秒以上かかるため、私たちにとっては耐えられません。さらに、非常に高速 (ミリ秒単位) に実行されるはずの SQL クエリの一部が、アプリケーションの観点からは実際には 100 ミリ秒以上かかっていることもわかりましたが、MySQL データベースの観点からは完全に正常であり、クエリが遅いという問題は見つかりませんでした。

トラブルシューティングを通じて、クラスター内のリクエストや外部リソースおよび外部訪問者が関与するリクエストなど、Kubernetes ノードとの接続を確立するリンクに問題が絞り込まれました。この問題を再現する最も簡単な方法は、Vegeta を使用して、任意の内部ノードで NodePort として公開されているサービスに対して HTTP ストレス テストを開始することです。時々、レイテンシの高いリクエストが生成されていることがわかります。この投稿では、この問題をどのように追跡したかについて説明します。

霧を晴らし、問題の鍵を見つける

問題を再現するために簡単な例を使用し、問題の範囲を絞り込み、不必要な複雑さを排除したいと考えています。当初、Vegeta と Kubernetes Pod 間のデータフローに関係するコンポーネントが非常に多く、これがより深刻なネットワークの問題であるかどうかを判断するのが困難だったため、減算を行う必要がありました。

Vegeta クライアントは、クラスター内の Kube ノードへの TCP 要求を開始します。当社のデータセンターの Kubernetes クラスターは、Overlay ネットワーク (既存のデータセンター ネットワーク上で実行) を使用しており、Overlay ネットワークの IP パケットをデータセンターの IP パケットにカプセル化します。リクエストが最初の kube ノードに到着すると、NAT 変換が実行され、kube ノードの IP とポートがオーバーレイのネットワーク アドレス、具体的にはアプリケーションを実行している Pod の IP とポートに変換されます。応答を要求すると、対応する逆変換 (SNAT/DNAT) が行われます。これは非常に複雑なシステムであり、多くの変更可能な状態を維持し、サービスが展開されるたびに常に更新されます。

初めて Vegeta を使用してストレス テストを実行したとき、TCP ハンドシェイク フェーズ (SYN と SYN-ACK の間) に遅延があることがわかりました。 HTTP と Vegeta によってもたらされる複雑さを簡素化するために、hping3 を使用して SYN パケットを送信し、応答パケットが遅延しているかどうかを観察してから接続を閉じます。遅延が 100 ミリ秒を超えるパケットをフィルタリングして、Vegeta のレイヤー 7 ストレス テストを簡単に再現したり、SYN 攻撃にさらされているサービスをシミュレートしたりできます。次のログは、TCP SYN/SYN-ACK パケットを kube-node のポート 30927 に 10 ミリ秒間隔で送信し、遅いリクエストをフィルタリングした結果を示しています。

 theojulienne @ shell ~ $ sudo hping3 172.16 .47 .27 - S - p 30927 - i u10000 | egrep -- 行- バッファリングされた'rtt=[0-9]{3}\.'
 長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 1485、 勝利= 29200、 RTT = 127.1 ミリ秒
長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 1486、 勝利= 29200 、 RTT = 117.0 ミリ秒
長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 1487、 勝利= 29200、 RTT = 106.2 ミリ秒
長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 1488、 勝利= 29200 、RTT = 104.1 ミリ秒
長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 5024、 勝利= 29200、 RTT = 109.2 ミリ秒
長さ= 46、 IP = 172.16.47.27 、 TTL = 59、 DF ID = 0 、 スポーツ= 30927、 フラグ= SA、 シーケンス= 5231、 勝利= 29200、 RTT = 109.2 ミリ秒

ログ内のシーケンス番号と時間に基づいて、この遅延は単発的に発生するものではなく、バックログのリクエストが一度に処理されているかのように、クラスターで頻繁に発生することが最初に確認されました。

次に、どのコンポーネントに例外がある可能性があるかを具体的に特定します。数百行に及ぶので、これは kube-proxy NAT ルールでしょうか?それとも、IPIP トンネリングや同様のネットワーク コンポーネントのパフォーマンスが低いのでしょうか?トラブルシューティングの 1 つの方法は、システムの各ステップをテストすることです。 NAT ルールとファイアウォール ロジックを削除し、IPIP トンネリングのみを使用するとどうなりますか?

kube-node を使用している場合は、Linux で Pod と直接通信できます。これは非常に簡単です。

 theojulienne @ kube - node - client ~ $ sudo hping3 10.125 .20 .64 - S - i u10000 | egrep -- 行- バッファリングされた'rtt=[0-9]{3}\.'
 長さ= 40、 IP = 10.125.20.64 、 TTL = 64、 DF ID = 0、 スポーツ= 0 、 フラグ= RA、 シーケンス= 7346 、 勝利= 0、 RTT = 127.3 ミリ秒
len = 40 ip = 10.125 .20 .64 ttl = 64 DF id = 0 sport = 0 flags = RA seq = 7347 win = 0 rtt = 117.3 ms
 長さ= 40、 IP = 10.125.20.64 、 TTL = 64、 DF ID = 0、 スポーツ= 0 、 フラグ= RA、 シーケンス= 7348 、 勝利= 0、 RTT = 107.2 ミリ秒

結果から、問題はまだ存在していることがわかります。これにより、iptables と NAT が問題になることがなくなります。 TCPに何か問題がありますか? ICMP リクエストを使用した場合に何が起こるかを見てみましょう。

 theojulienne @ kube - node - client ~ $ sudo hping3 10.125 .20 .64 -- icmp -i u10000 | ​ egrep -- 行- バッファリングされた'rtt=[0-9]{3}\.'
 長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 42594 icmp_seq = 104 rtt = 110.0 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 49448 icmp_seq = 4022 rtt = 141.3 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 49449 icmp_seq = 4023 rtt = 131.3 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 49450 icmp_seq = 4024 rtt = 121.2 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 49451 icmp_seq = 4025 rtt = 111.2 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 49452 icmp_seq = 4026 rtt = 101.1 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 50023 icmp_seq = 4343 rtt = 126.8 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 50024 icmp_seq = 4344 rtt = 116.8 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 50025 icmp_seq = 4345 rtt = 106.8 ミリ秒
長さ= 28 ip = 10.125 .20 .64 ttl = 64 id = 59727 icmp_seq = 9836 rtt = 106.1 ミリ秒

結果は、ICMP が依然として問題を再現できることを示しています。それで、問題の原因は IPIP トンネルですか?問題をさらに単純化してみましょう。

では、これらのノード間の通信によってこの問題が発生する可能性はあるのでしょうか?

 theojulienne @ kube - node - client ~ $ sudo hping3 172.16 .47 .27 -- icmp -i u10000 | ​ egrep -- 行- バッファリングされた'rtt=[0-9]{3}\.'
 長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 41127 icmp_seq = 12564 rtt = 140.9 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 41128 icmp_seq = 12565 rtt = 130.9 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 41129 icmp_seq = 12566 rtt = 120.8 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 41130 icmp_seq = 12567 rtt = 110.8 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 41131 icmp_seq = 12568 rtt = 100.7 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 9062 icmp_seq = 31443 rtt = 134.2 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 9063 icmp_seq = 31444 rtt = 124.2 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 9064 icmp_seq = 31445 rtt = 114.2 ミリ秒
長さ= 46 ip = 172.16 .47 .27 ttl = 61 id = 9065 icmp_seq = 31446 rtt = 104.2 ミリ秒

この複雑さの背後には、簡単に言えば、ICMP を含む 2 つの kube ノード間のネットワーク通信が存在します。このターゲット ノードが「異常」である場合 (一部のノードが他のノードよりも悪い、つまりレイテンシが高く、問題が頻繁に発生する)、問題が発生したときに同様のレイテンシが引き続き発生します。

それで、問題は、明らかにすべてのマシンでこの問題が発生するわけではないのに、なぜこの問題が kube-node サーバーでのみ発生するのかということです。これは、kube ノードがリクエストの送信側またはリクエストの受信側のときに発生しますか?幸いなことに、問題を簡単に絞り込むことができます。クラスター外部のマシンを送信元として使用し、同じ「既知の障害」マシンをリクエストのターゲットとして使用することができます。この方向のリクエストにはまだ問題があることがわかりました。

 theojulienne @ shell ~ $ sudo hping3 172.16 .47 .27 - p 9876 - S - i u10000 | egrep -- 行- バッファリングされた'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 -- 行- バッファリングされた'rtt=[0-9]{3}\.'
 ^ C さん
-- - 172.16 .33 .44 hping 統計-- -
 送信パケット数22352 、 受信パケット数22350 、 パケット損失1 %
 往復の最小/ 平均/ 最大= 0.2 / 7.6 / 1010.6 ミリ秒

パケットキャプチャのレイテンシデータを確認すると、より多くの情報が得られます。具体的には、送信側では遅延が発生します (下図)。一方、受信側サーバーでは遅延は発生しません (上図)。Delta 列 (秒単位) に注意してください。

さらに、受信側での TCP と ICMP ネットワーク パケットの順序の違い (シーケンス ID に基づく) を調べたところ、ICMP パケットは常に送信された順序で受信側に到着しますが、配信時間は不規則であることがわかりました。一方、TCP パケットはシーケンス ID が絡み合って一時停止することがあり、一部のパケットが停止します。特に、SYN パケットが送受信されるポートを数えると、送信側ではポートが順番に並んでいますが、受信側では順番に並んでいません。

当社のサーバーで現在使用されているネットワーク カード (当社のデータ センターで使用しているハードウェアなど) では、TCP および ICMP ネットワーク メッセージの処理方法に微妙な違いがあります。データグラムが到着すると、NIC は各接続で送信されたパケットをハッシュし、異なる接続を異なる受信キューに割り当てようとし、各キューを (おおよそ) 1 つの CPU コアに割り当てます。 TCP パケットの場合、このハッシュ値には送信元 IP、ポートと宛先 IP、ポートの両方が含まれます。つまり、各接続のハッシュ値は異なる可能性があります。 ICMP パケットの場合、ポートがないため、ハッシュ値には送信元 IP と宛先 IP のみが含まれます。これも上記の調査結果を説明しています。

もう 1 つの新たな発見は、2 つのホスト間の ICMP パケットが一定期間スタックしていたのに対し、同じ期間 TCP パケットは正常であったことです。これは、受信 NIC キューのハッシュが私たちを騙していることを示しているようで、送信側ではなく、RX パケットの処理中に受信側でストールが発生していることはほぼ確実です。

これにより、kube ノード間の送信の問題が排除され、パケット処理フェーズで停止が発生し、受信側はいずれかの kube ノードであることがわかります。

Linuxカーネルのネットワークパケット処理を深く掘り下げる

kube-node サービスの受信側で問題が発生する理由を理解するために、Linux がネットワーク パケットを処理する方法を見てみましょう。

最も単純かつ原始的な実装では、ネットワーク カードがネットワーク パケットを受信すると、Linux カーネルに割り込みを送信して、処理する必要があるネットワーク パケットがあることを通知します。カーネルは、実行中の他の処理をすべて停止し、コンテキストを割り込みハンドラに切り替え、ネットワーク メッセージを処理し、その後、前のタスクに戻ります。

コンテキストの切り替えは非常に遅くなります。これは 1990 年代の 10Mbit NIC では問題なかったかもしれませんが、現在多くのサーバーには 10Gbit NIC が搭載されており、1 秒あたり最大 1,500 万パケットを処理できます。つまり、小規模な 8 コア サーバーでは、1 秒あたり数百万回の割り込みが発生することになります。

何年も前に、Linux は従来の方法に代わる新しい NAPI (Networking API) を追加しました。最新のネットワーク カード ドライバーは、この新しい API を使用して、高速パケット処理のパフォーマンスを大幅に向上させます。低レートの場合でも、カーネルは上記のようにネットワーク カードからの割り込みを受け入れます。しきい値を超えるパケットが到着すると、カーネルは割り込みを無効にし、ネットワーク カードのポーリングを開始して、ネットワーク パケットをバッチでキャプチャします。このプロセスは、「softirq」、つまりソフトウェア割り込みコンテキストとも呼ばれるコンテキストで実行されます。これは、プログラム実行がユーザー空間ではなくカーネル空間に入ったときに、システム コールの終了時に発生します。

この方法は従来の方法よりもはるかに高速ですが、別の問題も発生します。パケット数が非常に多く、ネットワーク カードから受信したパケットの処理に CPU 時間をすべて費やす場合、ユーザー モード プログラムがキューに入れられたネットワーク要求 (TCP 接続からデータを取得するなど) を実際に処理することを許可できません。最終的に、キューがいっぱいになり、パケットがドロップされ始めます。ユーザー モードとカーネル モードでの実行に費やされる時間のバランスをとるために、カーネルは特定のソフトウェア割り込みコンテキストによって処理されるパケットの数を制限し、「予算」を調整します。この「予算」を超えると、「ksoftiqrd」(または ps コマンドで表示されたもの) と呼ばれる別のスレッドが起動され、通常のシステム コール パスの外部でこれらのソフトウェア割り込みコンテキストの処理が継続されます。このスレッドは、公平なスケジューリングを可能にする標準のプロセス スケジューラを使用します。

Linux カーネルがネットワーク パケットを処理するパスを整理すると、この処理プロセスが実際に一時停止する可能性があることがわかりました。 softirq ハンドラ呼び出しの間隔が長くなると、ネットワーク パケットが NIC の RX キューにしばらく留まる可能性があります。これは、CPU コアのデッドロック、またはカーネルによるソフト IRQ の処理を​​ブロックする低速タスクが原因である可能性があります。

問題を核心または方法に絞り込む

現時点では、この遅延は確かに起こり得ると私たちは考えており、また、非常に類似した兆候がいくつか観察されているようだということもわかっています。次のステップは、この理論を確認し、問題の原因を理解することです。

問題のあるネットワーク要求をもう一度見てみましょう。

 長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29573 icmp_seq = 1953 rtt = 99.3 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29574 icmp_seq = 1954 rtt = 89.3 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29575 icmp_seq = 1955 rtt = 79.2 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29576 icmp_seq = 1956 rtt = 69.1 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29577 icmp_seq = 1957 rtt = 59.1 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29790 icmp_seq = 2070 rtt = 75.7 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29791 icmp_seq = 2071 rtt = 65.6 ミリ秒
長さ= 46 ip = 172.16 .53 .32 ttl = 61 id = 29792 icmp_seq = 2072 rtt = 55.5 ミリ秒

前に説明したように、これらの ICMP パケットは特定の NIC RX キューにハッシュされ、CPU コアによって処理されます。カーネルが何をしているのか理解したい場合、まずどの CPU コアがこれらのパケットを処理するのか、また softirq と ksoftiqrd がどのようにこれらのパケットを処理するのかを知る必要があります。これは、問題を特定するために非常に役立ちます。

ここで、Linux カーネルの実行状態をリアルタイムで追跡するのに役立つツールをいくつか使用できるようになりました。これには、bcc を使用できます。 bcc を使用すると、小さな C プログラムを記述してカーネル内の任意の関数にマウントし、イベントをキャッシュしてユーザー モードの Python プログラムに渡すことができます。ユーザー モードの Python プログラムでは、これらのイベントの概要分析が行われ、結果が返されます。上で述べた「カーネル内の任意の関数へのマウント」は実際には難しい点ですが、一般的にテスト環境や開発環境では容易に再現できないような本番環境の問題を追跡できるように設計されているため、可能な限り安全なものになっています。

私たちのアイデアは非常にシンプルです。カーネルが IMCP Ping パケットを処理していることがわかっているので、カーネルの icmp_echo メソッドをインターセプトします。このメソッドは、着信 ICMP「エコー要求」パケットを受け入れ、ICMP 応答「エコー応答」を開始します。これらのパケットは、hping3 に表示される icmp_seq シーケンス番号によって識別できます。

この bcc スクリプトのコードは複雑に見えるかもしれませんが、細かく分解してみるとそれほど怖いものではありません。 icmp_echo 関数には、ICMP エコー要求を含むデータ パケットである構造体 sk_buff *skb へのポインタが渡されます。少し調べて echo.sequence (上記の hping3 の icmp_seq に対応) を抽出し、それをユーザー空間に送り返すことができます。同時に、現在のプロセス名またはプロセス ID も簡単に取得できます。カーネルがこれらのパケットを処理すると、次の結果が表示されます。

 TGID PID プロセス名ICMP_SEQ
 0 0 スワッパー/ 11 770
 0 0 スワッパー/ 11 771
 0 0 スワッパー/ 11 772
 0 0 スワッパー/ 11 773
 0 0 スワッパー/ 11 774
 20041 20086 プロメテウス775
 0 0 スワッパー/ 11 776
 0 0 スワッパー/ 11 777
 0 0 スワッパー/ 11 778
 4512 4542 スポーク- レポート- s 779

ここでプロセス名について注目すべき重要な点は、システム コール後に発生するソフト IRQ のコンテキストでは、カーネル コンテキストでカーネルが処理しているにもかかわらず、システム コールを実行したプロセスが「プロセス」として表示されることです。

実行することで、hping3 によって観測された停止したパケットとそれを処理したプロセスを関連付けることができるようになりました。キャプチャされた icmp_seq 値を単純に grep すると、これらのパケットが処理される前に何が起こるかについてのコンテキストが提供されます。上記の hping3 に示されている icmp_seq 値に一致するパケットは、観測された rtt 値とともにマークされます (括弧内の値は、RTT < 50ms のリクエストはフィルタリングされないと想定していることを示しています)。

 TGID PID プロセス名ICMP_SEQ ** RTT
 --
 10137 10436 キャドアドバイザー1951
 10137 10436 キャドアドバイザー1952
 76 76 ksoftirqd / 11 1953 ** 99 ミリ秒
76 76 ksoftirqd / 11 1954 ** 89 ミリ秒
76 76 ksoftirqd / 11 1955 ** 79 ミリ秒
76 76 ksoftirqd / 11 1956 ** 69 ミリ秒
76 76 ksoftirqd / 11 1957 ** 59 ミリ秒
76 76 ksoftirqd / 11 1958 ** ( 49 ミリ秒)
 76 76 ksoftirqd / 11 1959 ** ( 39 ミリ秒)
 76 76 ksoftirqd / 11 1960 ** ( 29 ミリ秒)
 76 76 ksoftirqd / 11 1961 ** ( 19 ミリ秒)
 76 76 ksoftirqd / 11 1962 ** ( 9 ミリ秒)
 --
 10137 10436 キャドアドバイザー2068
 10137 10436 キャドアドバイザー2069
 76 76 ksoftirqd / 11 2070 ** 75 ミリ秒
76 76 ksoftirqd / 11 2071 ** 65 ミリ秒
76 76 ksoftirqd / 11 2072 ** 55 ミリ秒
76 76 ksoftirqd / 11 2073 ** ( 45 ミリ秒)
 76 76 ksoftirqd / 11 2074 ** ( 35 ミリ秒)
 76 76 ksoftirqd / 11 2075 ** ( 25 ミリ秒)
 76 76 ksoftirqd / 11 2076 ** ( 15 ミリ秒)
 76 76 ksoftirqd / 11 2077 ** ( 5 ミリ秒)

上記の結果からいくつかのことがわかります。まず、これらのパケットは ksoftirqd/11 プロセスによって処理されます。これは、この特定のマシンが ICMP パケットを受信者の CPU コア 11 にハッシュしていることを便利に伝えます。また、ストールが発生するたびに、cadvisor の syscall softirq コンテキストでいくつかのパケットが処理されていることが常に確認され、その後、ksoftirqd が引き継いでバックログを処理します。このバックログは、ストールが発生したパケットに対応しています。

cAdvisor が常にスタックしたリクエストの直前に実行されるという事実は、これがトラブルシューティング中の問題に関連している可能性があることを示唆しています。皮肉なことに、cAdvisor ホームページに記載されているように、私たちは「実行中のコンテナのリソース使用量とパフォーマンス特性を分析」するために cAdvisor を使用していましたが、それがこのパフォーマンスの問題を引き起こしました。コンテナに関連する多くのものと同様に、これらは比較的最先端のツールであり、予期しないパフォーマンスの低下につながる可能性があります。

cAdvisor は一時停止を引き起こすために何をしましたか?

ストールがどのように発生するか、ストールを引き起こすプロセス、およびストールが発生する CPU コアがわかったので、ストールについて十分に理解できました。カーネルが事前に ksoftirqd をスケジュールするのではなくハードブロックするために、また cAdvisor の softirq のコンテキストで処理されるパケットを確認するために、cAdvisor の syscall 呼び出しが非常に遅くなる可能性があり、それが完了すると残りのネットワーク パケットは正常に処理できると考えられます。

これは単なる理論なので、これが実際に起こっていることをどうやって確認できるのでしょうか?私たちができることは、このプロセス全体を通じて CPU コアで何が実行されているかを追跡し、パケットが「予算」を超えて ksoftirqd プロセスを起動し始めるポイントを見つけて、CPU コアで何が実行されているかを振り返ることです。数ミリ秒ごとに CPU の X 線写真を撮影するようなものと考えてください。次のようになります:

この要件の詳細な調査はすでに完了しています。 perf レコード ツールは、指定された CPU コアを特定の周波数でサンプリングし、リアルタイムの呼び出しグラフ (ユーザー スペースとカーネルを含む) を生成できます。このツールは、Brendan Gregg が開発した FlameGraph から派生したプログラムを使用してライブ呼び出しを記録および操作し、スタック トレースの順序を保持します。 1 ミリ秒ごとにサンプリングすることで 1 行のスタック トレースを取得し、次に ksoftirqd が実行される前の 100 ミリ秒のサンプルを取得できます。

 # 1 秒間に999 回記録、 またはタイマーと正確に一致しないようにオフセットを付けて1 ミリ秒ごとに記録します
sudo パフォーマンスレコード-C 11 -g -F 999
 # その記録を取って、 より単純なスタックトレースを作成します。
 sudo perf スクリプト2 > /dev/ null | 。 / FlameGraph / stackcollapse - パフォーマンス- 順序付け。 翻訳するgrep ksoftir - B 100

結果は次のとおりです。

（似たような痕跡が何百個も）

 キャドアドバイザー; [ cadvisor ] ; ​​​​​​​​​​entry_SYSCALL_64_after_swapgs ; 64 を実行します。 sys_read ; 読み取り専用シーケンス読み取り; 統計情報を表示します。 mem_cgroup_nr_lru_ページ; mem_cgroup_node_nr_lru_ページ
キャドアドバイザー; [ cadvisor ] ; ​​​​​​​​​​entry_SYSCALL_64_after_swapgs ; 64 を実行します。 sys_read ; 読み取り専用シーケンス読み取り; 統計情報を表示します。 mem_cgroup_nr_lru_ページ; mem_cgroup_node_nr_lru_ページ
キャドアドバイザー; [ cadvisor ] ; ​​​​​​​​​​entry_SYSCALL_64_after_swapgs ; 64 を実行します。 sys_read ; 読み取り専用シーケンス読み取り; 統計情報を表示します。 メモリグループイター
キャドアドバイザー; [ cadvisor ] ; ​​​​​​​​​​entry_SYSCALL_64_after_swapgs ; 64 を実行します。 sys_read ; 読み取り専用シーケンス読み取り; 統計情報を表示します。 mem_cgroup_nr_lru_ページ; mem_cgroup_node_nr_lru_ページ
キャドアドバイザー; [ cadvisor ] ; ​​​​​​​​​​entry_SYSCALL_64_after_swapgs ; 64 を実行します。 sys_read ; 読み取り専用シーケンス読み取り; 統計情報を表示します。 mem_cgroup_nr_lru_ページ; mem_cgroup_node_nr_lru_ページ
ksoftirqd / 11 ; フォークから戻ります。 kスレッド; kスレッド; smpboot_thread_fn ; smpboot_thread_fn ; 実行_ksoftirqd ; __do_softirq ; ネットアクション; ixgbe_poll ; inet_gro_receive ; ボンドハンドルフレーム; __netif_receive_skb_core ; ip_rcv_finish ; ip_rcv ; ip_forward_finish ; ip_forward ; ip_finish_output ; nf_iterate ; ip_出力; ip_finish_output2 ; __dev_queue_xmit ; dev_hard_start_xmit ; ipip_tunnel_xmit ; ip_tunnel_xmit ; iptunnel_xmit ; ip_local_out ; dst_出力; __ip_local_out ; 遅いです; nf_iterate ; 戻り値: 汎用パケット; ipt_do_table ; マッチv4を設定します。 ip_set_test ; ハッシュ_net4_kadt ; ixgbe_xmit_frame_ring ; swiotlb_dma_mapping_error ; ハッシュ_net4_テスト
ksoftirqd / 11 ; フォークから戻ります。 kスレッド; kスレッド; smpboot_thread_fn ; smpboot_thread_fn ; 実行_ksoftirqd ; __do_softirq ; ネットアクション; gro_cell_poll ; napi_gro_receive ; 内部ネットワークinet_gro_receive ; __netif_receive_skb_core ; ip_rcv_finish ; ip_rcv ; ip_forward_finish ; ip_forward ; ip_finish_output ; nf_iterate ; ip_出力; ip_finish_output2 ; __dev_queue_xmit ; dev_hard_start_xmit ; dev_queue_xmit_nit ; パケット_rcv ; tパケット_rcv ; sch_direct_xmit ; 検証_xmit_skb_list ; 検証_xmit_skb ; 機能ixgbe_xmit_frame_ring ; swiotlb_dma_mapping_error ; __dev_queue_xmit ; dev_hard_start_xmit ;

ログは多数ありますが、その中に cAdvisor、次に ksoftirqd という固定パターンが見つかるかもしれません。それで、これは何を意味するのでしょうか?

各行は、特定の瞬間のトレースの記録です。呼び出されたメソッド スタック内の各メソッドはセミコロンで区切られます。行の真ん中で、呼び出されるシステムコールがread(): ...;doであることがわかります。   syscall_64;sys_read;... cAdvisorは、mem_cgroupに関連するread()システムコールの呼び出しに多くの時間を費やしています。   * 関数は、メソッド スタックの一番下にあるメソッドであるため、この関数は使用されません。

スタック トレースでは読み取りの具体的な内容を簡単に表示することはできないため、strace を使用して cAdvisor が何を実行しているかを確認し、100 ミリ秒以上かかるシステム コールを見つけることができます。

 theojulienne @ kube - node - bad ~ $ sudo strace - p 10137 - T - ff 2 > & 1 | egrep '<0\.[1-9]'
 [ pid 10436 ] < ... futex が再開されました> ) = 0 < 0.156784 >
 [ pid 10432 ] < ... futex が再開されました> ) = 0 < 0.258285 >
 [ pid 10137 ] < ... futex が再開されました> ) = 0 < 0.678382 >
 [ pid 10384 ] < ... futex が再開されました> ) = 0 < 0.762328 >
 [ pid 10436 ] < ... 読み取り再開> "cache 154234880\nrss 507904\nrss_h" ... 、 4096 ) = 658 < 0.179438 >
 [ pid 10384 ] < ... futex が再開されました> ) = 0 < 0.104614 >
 [ pid 10436 ] < ... futex が再開されました> ) = 0 < 0.175936 >
 [ pid 10436 ] < ... 読み取り再開> "cache 0\nrss 0\nrss_huge 0\nmapped_" ... 、 4096 ) = 577 < 0.228091 >
 [ pid 10427 ] < ... 読み取り再開> "cache 0\nrss 0\nrss_huge 0\nmapped_" ... 、 4096 ) = 577 < 0.207334 >
 [ pid 10411 ] < ... epoll_ctl が再開されました> ) = 0 < 0.118113 >
 [ pid 10382 ] < ... pselect6 が再開されました> ) = 0 ( タイムアウト) < 0.117717 >
 [ pid 10436 ] < ... 読み取り再開> "cache 154234880\nrss 507904\nrss_h" ... 、 4096 ) = 660 < 0.159891 >
 [ pid 10417 ] < ... futex が再開されました> ) = 0 < 0.917495 >
 [ pid 10436 ] < ... futex が再開されました> ) = 0 < 0.208172 >
 [ pid 10417 ] < ... futex が再開されました> ) = 0 < 0.190763 >
 [ pid 10417 ] < ... 読み取り再開> "cache 0\nrss 0\nrss_huge 0\nmapped_" ... 、 4096 ) = 576 < 0.154442 >

この時点で、read() システム コールが遅いことはほぼ確実です。読み取られたコンテンツと mem_cgroup のコンテキストから判断すると、これらの read() 呼び出しは、システムのメモリ使用量と cgroup 制限を記述するために使用される memory.state ファイルを読み取っています。 cAdvisor はこのファイルをポーリングして、コンテナで使用されるリソースの詳細を取得します。このメソッドを手動で呼び出すことで、カーネルの問題か cAdvisor の問題かを確認できます。

 theojulienne @kube - node - bad ~ $ time cat / sys / fs / cgroup / memory / memory 。 統計> / dev/ ヌル
実数0 分 0 秒153 秒
ユーザー0 分0 .000 秒
システム0 分0.152 秒
theojulienne @ kube - ノード- 悪い~ $

この問題を再現できることから、これはカーネルによって引き起こされる「異常な」方法であることが示唆されます。

この読み取りが遅い原因は何ですか?

さて、この段階では、他の人が報告した同様の問題を簡単に調べることができます。この問題はすでに cAdvisor に報告されており、CPU 使用率が高いことが原因であることが判明しましたが、遅延がネットワーク スタックにもランダムに影響を与えていることは認識されていませんでした。実際、一部の社内開発者は cAdvisor が予想以上に CPU を消費していることに気づいていますが、弊社のサーバーには十分な CPU パフォーマンスがあるため、問題は発生していないようです。そのため、CPU 使用率については調査していません。

この質問を見ると、主に、名前空間 (コンテナ) 内のメモリ使用量の管理とカウントを担当するメモリ cgroup に関するものです。 cgroup 内のすべてのプロセスが終了すると、メモリ cgroup は Docker によって解放されます。ただし、「メモリ」はプロセスのメモリだけではありません。プロセスのメモリ使用量はなくなる一方で、カーネルは、メモリ cgroup にキャッシュされる dentry や inode (ディレクトリとファイルのメタデータ) などのキャッシュ領域にもメモリを割り当てていることがわかります。この質問から次のことがわかります。

「ゾンビ」 cgroup: プロセスが実行されておらず、削除されているが、まだいくらかのメモリ領域を保持している cgroup (この場合、これらのキャッシュされたオブジェクトはディレクトリ データですが、ページ キャッシュや tmpfs の場合もあります)。

cgroup が解放されたときにすべてのキャッシュされたページを反復処理する代わりに (これは遅くなる可能性があります)、カーネルはメモリが必要になるまで待機してからメモリを再利用します。すべてのメモリ ページがクリーンアップされると、対応する cgroup が最終的に再利用されます。同時に、これらの cgroup は統計に引き続きカウントされます。

パフォーマンスの観点からは、各ページを分割して再利用することで、直接的なモノリシック再利用にかかる膨大な時間を短縮し、メモリ内にキャッシュを保持する高速な初期クリーンアップを選択します。しかし、これは問題ありません。カーネルがキャッシュ内のメモリの最後のページを再利用すると、cgroup は最終的にクリーンアップされるため、「リーク」にはなりません。残念ながら、問題は memory.stat が検索を実行する方法にあります。たとえば、一部のサーバーではカーネルがまだ 4.9 であり、実装にバグがあります。これに加えて、当社のサーバーには通常、大量のメモリ領域があるという事実により、最後の memcache の削除とゾンビ cgroup のクリーンアップには長い時間がかかる可能性があります。

ノードには多数のゾンビ cgroup があり、その一部では 1 秒を超える読み取り/停止が発生していることが判明しました。

この cAdvisor の問題に対する一時的な回避策は、システム全体のディレクトリ/inode キャッシュを直ちに解放することです。これにより、読み取り待ち時間が直ちになくなり、ネットワーク待ち時間も解決されます。これは、キャッシュの削除には「ゾンビ」cgroup によって使用されるキャッシュ ページも含まれ、同時に解放されるためです。これは最終的な解決策ではありませんが、問題の原因を確認することができます。

新しいカーネル バージョン (4.19 以降) では、memory.stat 呼び出しのパフォーマンスが向上しているため、そのバージョンのカーネルに更新すると、この問題は発生しなくなります。この間、私たちは既存のツールを使用して Kubernetes クラスター内のノードの問題を検出し、それらを正常に削除して再起動しました。これらのツールを使用してレイテンシを検出し、レイテンシが問題を引き起こすほど高いことが判明した場合は、正常な再起動で対処しました。これにより、残りのサーバーの OS とカーネルをアップグレードする間に、いくらかの余裕ができました。

要約する

この問題は、数百ミリ秒間の NIC RX キューの停止として現れるため、短い接続で高いレイテンシが発生するだけでなく、接続の途中 (たとえば、MySQL クエリと応答パケットの間) でもレイテンシが発生します。 Kubernetes のような最も基本的なシステムのパフォーマンスを理解し、維持することは、その上に構築されるすべてのサービスの信頼性と速度にとって重要です。これを実現し、パフォーマンスを向上させるために重要な技術「投資」を行うと、私たちが実行するすべてのシステムがこれらの改善の恩恵を受けます。