大規模Kafkaクラスターで起きたリクエスト遅延　どのように問題を特定して解決したか

TCP windowの概念について

岡田遥来氏：さて、このようにブローカーがSYN flood状態になって、一部のクライアントのhandshakeがSYN Cookiesを使ったフローにフォールバックしてしまっていたことがわかったわけですが、実はこのSYN Cookiesというのは、TCPスループットの悪化を引き起こすケースがあるということが知られています。これについて見るために、まずはTCP windowの概念について、ここで簡単に復習します。

TCP windowは、TCPにおいて流量制御を行うための仕組みです。大まかにいうと、TCPの受信側で今どれくらいデータを受け取れるのかを、TCPパケットに乗せて送信側にアドバタイズすることで、送信側が送るデータ量を調節して実現します。

送信側は、受信側からアドバタイズされたwindows sizeまでは、受信側からのACKを待つことなくパケットを一気に送信します。このwindow sizeは16ビットとTCPの資料で定められているため、65,535が最大値となります。

つまり、ここではサーバーが受信側としますが、サーバーからのACKを待たずに1度に送れるデータの量というのは、最大でも65,535バイトとなります。

少なくとも65,530バイトごとにサーバーからのACKが発生するということになりますが、例えばインターネットのようなラウンドトリップタイムが大きいコネクションにおいて、これがボトルネックになってしまうことがあります。

このような場合において、window sizeを65,535以上に広げてスループットを向上するために使われるのが、window scalingという仕組みです。

window scalingでは、まずTCP handshakeの際に、SYNおよびSYN ACKに載せて、window scaling factorという数値を相手にアドバタイズしておきます。

そのうえで実際にデータを送受信する際のwindow sizeを、パケットに含まれる16ビットのwindow sizeに対して、あらかじめやり取りしておいたwindow scaling factorを使って「2のwindow scaling factor乗」を掛けて計算するようにします。

このようにすることで、window sizeを65,535を超えて大きくできるようになり、ACKを待たずに1度に送れるデータの量が増えて、スループットの向上が期待できるというわけです。

これについてちょっと例で見てみましょう。handshakeの際、サーバーからクライアントにあらかじめwindow scaling factorが「1」であるとアドバタイズしておいたとします。この時、サーバーがクライアントに「window size『102,400』」という値をアドバタイズしたいとします。これは65,535を超えていますので、単純にパケットに載せることはできません。

ですが、window scaling factorは「1」とあらかじめやり取りしてありますので、サーバー側はアドバタイズするwindow sizeを「2の1乗」、つまり2で割って、51,200をパケットに載せてアドバタイズします。クライアント側では、それに「2の1乗」を掛けることでオリジナルの102,400を復元できます。

このような仕組みで65,535を超えるようなwindow sizeをアドバタイズができるようになります。

SYN Cookiesでスループットが落ちうるケース

さて、window sizeおよびwindow scalingについて簡単に見てきたところで、もともと話題にしていたSYN Cookiesにおいてスループットが落ちてしまう理由の話に戻ります。

SYN Cookiesは、SYN QueueにSYNパケットをストアする代わりに、うまいことSYNの情報をTCP sequence numberにエンコードして、SYN ACKに埋め込むという仕組みでした。

ですが、このsequence numberはたった32ビットしかなくて、埋め込める情報は非常に限られているため、window scaling factorを埋め込む場所がありません。つまり、SYN Cookiesでhandshakeを行った場合は、window scalingが使えないということになります。

これによって、window sizeが、本来SYN Cookies経由でなければwindow scalingを使って大きくできたはずの値よりもだいぶ小さくなってしまって、ACKを待たずに1度に送れるデータが少なくなって、スループットが悪くなってしまうというわけです。

SYN Cookiesが原因なのか

さて、ではこれがProduceのリクエスト遅延を引き起こした原因なのでしょうか。実は結論づけるにはまだ早すぎます。

SYN CookiesにおけるTCPのスループットの悪化は、window scaling factorを埋め込むスペースがないために、window scalingが使えなくなってしまって発生していました。

ですが、実はLinuxカーネルには、TCP timestampというものが有効な場合は、timestampフィールドを余分に使ってwindow scaling factorを埋め込むという仕組みがあります。そして私たちの環境において、TCP timestampはデフォルトで有効になっています。したがって、先ほど見たスループットの悪化が発生し得るとは考えにくい状況でした。

さらに加えて、たとえwindow scaling factorが無効になってしまったとしても、今回のような急激なリクエストの遅延を引き起こし得るかというのは疑問でした。

なぜかというと、window scalingというのは、window sizeを65,535よりも大きくするための仕組みでした。これはインターネットのようなラウンドトリップタイムが大きいネットワークにおいては特に有効ですが、私たちの環境のように、非常に小さいレイテンシーで接続された環境においては、たとえwindow scalingが使えなくなって65,535が最大のwindow sizeとなってしまっても、スループットは十分確保できると考えられました。

そこで私たちは、SYN Cookiesにおいてwindow scalingが無効になってしまうことで、実際にどのぐらいの影響が発生し得るのか、これを実験してみることにしました。

この実験では「net.ipv4.tcp_syncookies」というLinuxのカーネルパラメータを「2」に設定することで、SYN floodが起きるか、起きているかどうかにかかわらず、すべてのコネクションをSYN Cookiesを使って確立するように強制したうえで、ブローカーを再起動してみて再現を試みるという実験です。

window scalingが有効な状態で現象が再現

さてその結果は、まったく予想していなかったことに、TCP timestampをまず無効にする前の段階、つまりwindow scalingが有効なはずの状態で、現象が再現してしまいました。

本番環境で起きた現象と同じく、Producer側におけるリクエストレイテンシーが、500ミリ秒という非常に高い数値を示しているにもかかわらず、ブローカー側のレスポンスタイムはいたって正常なままという状況です。

この時のtcpdumpを取ってみると、驚くべきことに、Producerがパケットを1つ送信するたびに、ブローカーからのACKを待っているということがわかりました。

これはブローカー側のwindow sizeが小さいために、ブローカーからACKを受け取るまでProducerが後続のパケットを送り出せていない状況だと考えられます。

ブローカー側のwindow sizeはtcpdumpを見ると「789」であることがわかります。つまり実際のwindow sizeはこれに「2のwindow scaling　factor乗」を掛け算したものになります。

ということで同じくtcpdumpでSYN ACKパケットを確かめてみると、ブローカーがProducerにアドバタイズしたwindow scaling factorが「1」であることがわかりました。つまり、実際のwindow sizeは「789 * 2 = 1,578」と、実際に非常に小さい値だということがわかりました。

なぜwindow sizeが小さな値になっているのか

したがって、次のステップとして、なぜwindow sizeがこのような小さな値になってしまっているのか調べることにしました。

私たちがここで使ったのは、ssというソケットの状態を調べるためのツールです。このssというツールは「’-i’ option」を指定することで、window scaling factorやCongestionのwindowのサイズ、またTCP timestampが有効かどうかといった、TCPの詳細な情報を見ることができます。

このssを現象の発生しているブローカーで実行してソケットの状態を調べてみると、またしても奇妙なことがわかりました。

ssの出力を見ると、ブローカー側のwindow scaling factorが「7」であると出力しています。ですが先ほどtcpdumpで見たように、SYN ACKではwindow scaling factorが「1」であると、Producer側にアドバタイズしたはずでした。

先ほどwindow scaling factorを使ってwindow sizeを計算する例で見たように、クライアントとサーバー、ここではProducerとブローカーですが、両者が保持しているwindow scaling factorが一致していないと、ブローカーからアドバタイズされてきたwindow sizeからオリジナルのwindow sizeを正しく復元することができませんから、これは当然一致していなければなりません。

どちらの値が正しいのか

次に実際にブローカー側でアドバタイズするwindow sizeを計算するために使っているのが、この「1」なのか「7」なのか、どちらなのかを確かめることにしました。

Linuxカーネルのソースコードを確認してみると、このwindow sizeの計算は、tcp_select_windowというカーネル関数で行っていることがわかりました。

この関数の引数のsock構造体にwindow scaling factorが含まれているので、どうにかしてこれをフックしてダンプできないかと考えました。

さて、どうすればこういったカーネル関数をフックできるでしょうか。これにはBPFというLinuxの仕組みを使うと、非常に簡単に実現できます。

BPFを使うと、ユーザーが作成したプログラムを、カーネル内部で実行することができます。BPFはイベント駆動の仕組みで、さまざまなイベントをトリガーに、BPFプログラムをトリガーにできますが、その中でkprobeというものを使うと、カーネル関数をフックすることが可能です。

そして、また世の中にはBPF Compiler Collection、bccと呼ばれるツールキットがあって、これを使うと、C言語を使って簡単にBPFのプログラムを記述できます。

このbccを使ってtcp_select_windowをフックして、window scaling factorを確かめる簡単なスクリプトを書いてみました。これを使って実際のブローカーで実行してみると何がわかったかというと、実際にProducerに送った「1」ではなくて、ssが出力した「7」、これを使ってwindow sizeを計算していることがわかりました。

ではなぜこのように、ブローカーからProducerにSYN ACKでアドバタイズしておいたwindow scaling factorと、ブローカーが実際にコネクションを確立した後に使っているwindow scaling factorに食い違いが起きてしまっているのでしょうか。

もう1度カーネルのソースコードを確認してみたところ、window scaling factorを求めるためのロジックが、クライアントに送るSYN ACKパケットを生成する箇所と、SYN Cookiesを送った後クライアントからACKが送り返されてきて、そこに含まれたSYN Cookiesをデコードして実際にコネクションを確立する箇所で、違っていることがわかりました。

結論からいうと、これはLinuxカーネルバージョン5.10以前に存在していたバグで、これが原因で、このようなwindow scaling factorの食い違いが起きてしまっていたことがわかりました。

事象の全容

さて、これですべての謎が解けました。全体の流れを振り返ってみます。

まずブローカーを再起動したことで、たくさんのクライアントが一気に再接続をしてきて、ブローカーがSYN flood状態になりました。これによって運悪く、あるProducerのTCP handshakeがSYN Cookies経由にフォールバックしました。

そしてカーネル5.10以前に存在していたバグによって、ブローカーからProducerにSYN ACKでアドバタイズしたwindow scaling factorと、ブローカーが最終的にコネクションを確立した後に使うwindow scaling factorが食い違うことになりました。

そしてこの食い違いが原因で、Producer側において、ブローカーからアドバタイズされてきたwindow sizeを正しく復元できず、非常に小さい値になってしまいました。

どういうことかというと、まずブローカー側でProducerにwindow sizeをアドバタイズする時は、ブローカーはwindow scaling factorが「7」だと思っているので、Producer側で「2の7乗」を掛けてくれるだろうと思って、「2の7乗」で割ってwindow sizeを伝えます。

一方Producer側では、window scaling factorが「1」だと思っているので、「2の1乗」を掛け算してwindow sizeを復元しようとします。これによりProducer側で計算したwindow sizeが、実際の64分の1という非常に小さな値になってしまいました。

そしてこの小さすぎるwindow sizeによって、Producerは1パケット送るたびに、ブローカーからのACKを待つことになりました。この結果、Produceリクエストの送信自体に非常に時間がかかるようになり、Produceリクエストのタイムアウトを招いてしまった、というのが今回の事象の全容でした。