Apache Kafkaで発生した原因不明のパフォーマンス低下と、それを解決するためにやったこと

Apache Kafkaのパフォーマンス低下とその原因

河村勇人氏：よろしくお願いします。最初に自己紹介をします。河村勇人といいます。

LINEで全社向けのKafkaプラットフォームを提供しているチームのLeadingをやっています。

日頃の仕事としては、Reliability EngineeringとPerformance Engineeringをメインにやっていて、Dailyで約2,600億件のメッセージを捌いている大きなKafkaクラスタの運用などをやっています。

過去に話した経験としては、Kafka Summitで2017年・2018年にトークをしました。去年LINE DEVELOPER DAYというイベントでも話をしていて、これから話すこともゴリゴリの技術的な内容ですが、同じような内容に興味ある人はぜひ見てみてください。

今日話すのはトラブルシューティングについてですが、まずはどんな現象があったかをお話しします。

ある日、我々のKafkaクラスタにおいて、99パーセンタイルのProduceのレスポンスタイムが突然悪化するということが起きました。グラフに載せているのは一番顕著だったケースなんですが、一番悪いケースで10秒をマークしたという、かなり異常な数値が出ていました。

毎回ではありませんが、このイシューが起きると、まれにBrokerがクラスタから抜けてしまいます。その理由は、zookeeperのセッションがタイムアウトしてクラスタから抜けてしまうからで、レプリカが1個減るということが起きていました。

我々は社内システム向けにSLOを設定していて、99パーセンタイルのProduceのレスポンスタイムで40ms以下に設定しているのですが、それを大きく超えてしまっていますし、さらに、クラスタから抜けてしまうというイシューがもし2台同時に起きると、レプリカが一気に2つ減ってしまうということです。（min.insync.replicas=2に設定しているため）それだけで障害になってしまうので、かなりクリティカルなイシューとして調査を開始しました。

いくつか発見できたことがあったんですが、最初に見つかったこととしては、Kafkaの代表的な2つのスレッドプールであるリクエストハンドラスレッドとネットワークスレッド、これらのUtilizationがすごく上がっているのが見つかりました。

おもしろいのは、ネットワークスレッドのほうは、例えばリクエストがバースティングするようなケースでいくつかのスレッドのUtilizationが上がるようなことはあるんですが、全体が一気に上がるようなケースはあまりないんですね。

追加の調査でわかったこと

追加で調査を継続するともう1つ見つかったのが、我々は日々Brokerを動かしているJVMのGC timeのメトリックを取っているんですが、それが増えていました。厳密にはこれはGC timeではなくて、いわゆるJVMの「Stop the World」と呼ばれる時間のログを計測しているメトリックが増えてました。

実際、そのサーバに入ってローカルのログに書いている、application stopped timeというStop the Worldの経過時間を記録しているログを見てみると、実際に1秒を超えるようなpause timeがマークされていました。

このログは2つのログから構成されていて、上はpause timeの全体を表しています。そのあとに続くstopping threads tookというパートは、JVMがStop the World状態に入るためにアプリケーションスレッドを止めていくのですが、その止めるのにかかった時間がここに記録されています。ここが増えるのはあまりないケースです。

この時点で通常のGC等のイシューではないだろうなということは分かりました。

では、stopping threadsの部分が増えるのはどんなケースかというと、Javaのasync-profilerという非常に有名なツールを書かれている方がブログポストですごくいい説明をされているので、それを引用します。

JVMには「safepoint」というコンセプトがあります。safepointというのはJVMが特殊な処理、例えばGCやjstackを取るような処理をするために、アプリケーションスレッドをすべて止めてなにか処理をする、この実行状態のことを「safepointに入っている」といいます。

もう1つ、「safepoint sync」という状態もあります。これは、アプリケーションスレッドを止めるために、まずはJVMがあるフラグを上げるんですね。それを見たアプリケーションスレッドが自主的に自分たちを止めていくというフローになっているんですが、このフラグを上げてからすべてのアプリケーションスレッドが止まり切るまでのこの部分のことを「safepoint sync」と読んでいます。

今回そのログが示しているのはこの部分が増えてますよ、ということです。これは、普通はあまり起きないです。

ディスクのアクセスタイムが増加していた

もう少し調査を継続してみると、別の発見として、当該時間にそのマシンのディスクのアクセスタイムが非常に伸びているのが見つかりました。

これらの発見を合わせて考えてみた時にあり得るシナリオとして1つ思い至ったのは、JVMがsafepointに入ったあとに何かしらのディスクアクセスをしていて、このディスクアクセスが遅いという場合です。

safepointはアプリケーションスレッドを全部止めている状態なので、ここが伸びてしまうと、もちろんアプリケーションが全部止まっているので、レイテンシが伸びるわけですね。

実はこの時点で、そのマシンで我々が使っているRAID controllerのファームウェアの実装に問題があって、その管理下にあるディスクが部分的に壊れて遅いレスポンスを返す状態になると、ぜんぜん関係ないボリュームまで巻き込みを食らって、全体のアクセスタイムが悪化する現象があることが分かりました。

疑ったポイント

今軽く言いましたが、実はここに至るまでに調査の50パーセントぐらいの時間は過ぎていて、かなりいろいろなところを右往左往した結果、ようやくたどり着きました。

とにかく疑ったのは、JVMがsafepointの中で書いているGCのログ、そのロギングの部分です。ですが、JVMはそのログを書くためにwrite(2)のシステムコールを使っているのですが、このwirte(2)のシステムコールははたしてブロックするのか？　という疑問があります。

実は、ファイルにどんどんコンテンツをappendしていくようなタイプのwrite(2)は、普通はブロックしません。なぜかというと、write(2)システムコールが中でやっていることというのは、カーネルの中の「page」というデータストラクチャにデータをコピーして、そのpageのdirty flagを上げるというだけの処理です。

ここでdirty flagが立ったpageというのは、Linuxカーネルの別のバックグラウンドで動いているwriteback taskが集めてきて、ディスクにフラッシュをして、dirty flagを下ろす処理をしています。なので、通常はwirite(2)システムコールを呼ぶというのは、ただメモリをコピーしているだけで、その中でブロックするということは起きないはずです。少なくともappendであれば。

ですが、やっぱりwrite(2)が怪しいということで、実際にそのJVMが呼んでるwrite(2)システムコールの実行時間を調べてみました。

ここで使ったのはSystemTapというツールです。これは私の過去のスライドで何度も話をしているので、詳細に興味がある人はそちらを参照していただければと思います。簡単に言うと、Linuxカーネルの中のさまざまなイベントを少しスクリプトを書くと観測できるようになる、Observability Toolと呼ばれるダイナミックトレーシングの一種です。

それを使ってJVMが呼んでるwrite(2)システムコールの実行時間を調べてみたら、実際に2秒を超えるような実行時間のものが見つかりました。

同時に、その時点でのバックトレースも出せるんですが、このバックトレースを見ながらOpenJDKの中のコードを読んでみると、確かにsafepointの中でログを書いていることがわかりました。

ということで、我々の大きな前提、「write(2)はブロックしないはずだ」という前提がここで崩れてしまいました。

なぜwrite(2)がブロックするのか

では、write(2)はブロックするかもしれないということがわかったので何か対策を考えるべきですが、まだ不十分だと思いました。なぜwrite(2)がブロックするかということを説明できていないので、そこがわからなければ本質的な対策ができません。なので、調査を継続しました。今度はなぜwrite(2)がブロックするのかということを調べます。

とりあえずなぜwrite(2)がブロックするかをわかるために、そのイシューが発生した時点でのプロセスのスタックのサンプリングを試みようとしたのですが、ここで問題が起きます。

2つ問題がありました。

1つは、このBrokerが動いていたマシンのディスクの故障具合がどんどん増えていったんだと思いますが、パフォーマンスイシューが起きる頻度がすごく高くなってアクセプトできないレベルにまでなってしまったので、そのBrokerをサービスアウトする必要がありました。

それからもう1つ、サービスアウトしたあとに継続してそのマシン上で実験をしていたんですが、私の書いたスクリプトのいくつかが、たまにカーネルをクラッシュさせることがありました。そのたびに、フィジカルなマシンだったので、インフラチームに「ハードリブートしてください」とお願いしてたんですが、ある時ハードリブートして戻ってきたら「ディスクが壊れたので交換しておきましたよ」と言われました。

私はドキっとして「これ、やばいんじゃないかな」と思って再現するはずのスクリプトを動かしたら、案の定再現しなくなってしまいました。もちろん親切にやってくださったんですが、結果的に再現する環境が失われてしまいました。

問題が起きた状況を再現する

ということで、じゃあ諦めるかというところなんですが、諦めませんでした。今、再現しなければいけないことは2つですね。

write(2)のワークロードを再現することと、ディスクが遅いレスポンスをしている状態をなんとか自分で再現できれば調査が継続できます。

write(2)のワークロードのほうは簡単ですね。本当にシンプルなプログラムを書いてファイルをオープンして、ファイルをwrite(2)して、その前後で実行時間を測って記録するだけで済むんですが、難しいのは、ディスクが遅いレスポンスをしていることです。こちらを再現するのは非常に難しい。

なぜかというと、write(2)自体が遅くなっているのを再現するのとは違うんですね。

write(2)というのはシステムコールでアプリケーションとカーネルの間のインターフェースなので、これを差し替えるのは比較的簡単なんですが、今知りたいのはこのwirte(2)の中で何が起きて遅くなっているかなので、この部分はちょっと難しいです。

最初に、Linuxカーネルの中の実装で、実際にそのカーネルの中でハードディスクなどのブロックデバイスに対してI/Oのリクエストを出す部分のゲートウェイのようになっているファンクションでgeneric_make_requestというファンクションがありますが、この部分をフックしてなんとかそこにディレイを差し込めないか試しました。

SystemTapを使ってファンクション部分をフックして、二重ループを無理やり回して、オーバーヘッドを差し込むということを試してみたのですが、これはぜんぜんうまくいきませんでした。

なぜかというと、SystemTapはそもそも安全にLinuxカーネルの中のさまざまなイベントをインスペクトするためにデザインされているツールなので、オーバーヘッドが高くなると自分で実行を止めてしまうセーフティの実装が入っています。なので、そもそもそういった恣意的なディレイを差し込むような用途には向きません。

ということで「どうしようかな？」とちょっと考えたんですけど、最終的に思いついたのは、Linuxのカーネルモジュールを自分で書くということでした。

SystemTapが使っている「kprobe」というインターフェースがあります。このkprobeというのはLinuxカーネルに提供されているAPIで、Linuxカーネルの任意のコード部分にブレークポイントを仕掛けてその処理を一時的に奪取できる機能を提供しているAPIなんですが、そのAPIを使って自分でカーネルモジュールを作りました。

今日説明するスクリプトやコード文は一通りgistにフルのバージョンを上げてあるので、詳細を見たい人は（スライドの）フッターのリンクを見ていただければと思います。

簡単に説明すると、generic_make_requestというファンクションに対して、register_kprobe()をします。このファンクションが呼ばれると、実行される直前にこのhandler_preが呼ばれます。このhandler_preは何をしているかというと、発行されたI/Oリクエストについて、I/Oのタイプがwriteで、かつ、sync flagが立っていて、ターゲットのデバイスIDが今そのレイテンシを差し込みたいものである場合、3回に1回サンプリングをして、300msのレイテンシを入れる、みたいな実装をしています。

これを実際に動かしてみたら、見事に再現できました。

generic_make_requestを読んだ時点でのタスクのIDとバックトレースを取れました。見てみると、ext4、システムボリュームについてはext4のファイルシステムを使っていたんですが、そのext4のjournalingをやっているカーネルのバックグラウンドタスクが引っかかりました。

関数の実行時間を調べる

ですが、「なぜそのjournalingタスクがI/Oのところでつっかかるとwrite(2)を呼んでいた別のプロセスが影響をくらうのか？」は説明できなかったんですね。なので、ちょっとアプローチを変えて別のサイドから調べてみることにしました。

今度やったのは、write(2)システムコールを呼んでいるそのプロセスがどの部分で遅くなっているのか、write(2)システムコールの中の関数のコールグラフを1個1個、どれぐらいの実行時間がかかっているかを調べました。

ここでも使っているのはSystemTapで、やっていることは非常にシンプルです。あるファンクションにエントリーしたタイミングとリターンしたタイミングで時間を記録して、その差分を実行時間としてどんどんappendして、最後にダンプするということをやっているだけです。

これはすごく地道な作業なんですが、バックトレースを取るのと違って上から順番に潜っていかないといけないので、1回1回まわしながら、どの部分で実行時間がかかったのか中のカーネルのソースを自分で読んで、対象のファンクションをどんどん追加していくという作業を行いました。非常に地道なんですが、それを14回ぐらいやったらようやくその欲しいものが手に入りました。

見てみると、今度は下から読む必要があるんですが、vfs_writeの中で呼ばれているgrab_cache_page_write_beginの中のfind_lock_pageの中のlockを取るところ。カーネルの中のpageというデータストラクチャがありますが、そのpageのlockを取るところでひっかかっていることがわかりました。

lock待ちの状態になってしまっているので、あとはそのlockをその時点で持っているのが誰なのかということを解析すれば良いわけです。ここで使ったテクニックもちょっとおもしろいのですが、今日は時間がないので端折ります。

いわゆるlock contentionの解析をやったところ、最終的に3段階の依存関係でこういうwrite(2)を呼んでるプロセスをブロックしていることがわかりました。

write(2)を呼んでいるプロセスはlockを取ろうとするんですが、そのlockはカーネルのwriteback taskが持っています。writeback taskもそのlockをリリースまでに長い時間かかるんですが、それはなぜかというと、こいつはこいつでext4のjournalingをしているデーモンが持っているjournal_headというデータストラクチャのバッファの状態が書き込み可能になるのを待っているという、3段階のcascadingな依存関係があるということがわかりました。

問題の全体像

最終的に全体像がクリアになったので、それをまとめたのがこの図です。

ちょっと大きすぎて見えないと思うので、ズームインしながらもう1回最初から辿ります。まずJVMです。

Kafka Brokerを動かしているJVMがあります。あるタイミングでその中のVMスレッドがsafepointに入ります。GCを実行するためなりjstackを実行するためなり、理由はなんでもいいんですが、safepointをオンにします。

そうすると、それを見たアプリケーションスレッドが「safepointに入らなきゃ」ということで自主的に休止状態に入ります。VMスレッドがsafepointの中のオペレーションを実行して、例えばGCを実行して、最後にログを書こうとします。write(2)を呼ぶわけですね。write(2)システムコールを呼びます。

そうすると、今度はコンテキストが変わって、カーネルの中におけるVMスレッドの挙動として、書き込みたい対象のページのlockを取ろうとします。

ですが、実はこのページのlockはこの時点で別なやつに取られています。

誰かというとカーネルのwriteback taskです。writeback taskがすでにこのページのlockを取っています。ですが、こいつもこいつで別のところでブロックされています。journal_headというデータストラクチャ、ext4のjournalingに関連したデータストラクチャがあるんですが、そのバッファがunshadowな状態、つまり書き込み可能な状態になるのを待ってます。

ではこのバッファの状態をshadowな状態にしているのは誰かというと、ext4のjournaling daemon taskです。このバッファをshadowな状態にしたあとに、実際のデバイスに対してgeneric_make_requestを経由してI/Oのリクエストをしています。この部分が遅かったのが今回の問題の本質です。

これがもともと遅かった理由は、RAID controllerのイシューによって、1本ディスクが壊れたらなぜか全体のボリュームが巻き込みを食らうという話です。後半の実験では、この部分の呼び出しに恣意的なディレイを差し込むことによって問題を再現しましたよ、というのが今回の全容です。

そのI/Oが返ってきてようやく、あとはトントン拍子でバッファがunshadowされて、このファイルのlockがunlockされてJVMまで処理が返ると、safepointを抜けられて、アプリケーションスレッドが全部resumeできて、というような流れになります。

いかにして解決するか？

「では、これをどうやって解決したらいいのか？」という話です。いくつかアイデアはあります。1つ目は、ファイルシステムを変えるか、ext4のjournalingを止めてしまうという手段ですね。

ですが、我々はオンラインで適用できる解決策が欲しかったので、別のアイデアとして、GCのロギングをしているそのログを書いているディレクトリをtmpfsに変えてしまうという解決を試しているところです。

それはJVMのオプションで変えられるので、ロギング先をtmpfsのディレクトリにします。とはいえ、volatileな、揮発性のある状態だと困るので、別のハードディスク領域にリアルタイムのバックアップを取りながら、ファイルが大きくなりすぎないうちにJVMのコマンドでGCファイルをローリングしていくという方法です。

これはまだプロダクションまで適用していませんが、比較的最近のイシューなので実験までは終わっていて、これで解決できるところまで確認できています。

ということで話をまとめると、少なくともext4をファイルシステムとして使っていて、かつ、その下で動いているディスクに部分的な故障があってレスポンスが悪くなるようなことがあった場合に、write(2)システムコールはブロックする可能性があります。

それを踏まえて、アプリケーションを書くときにwrite(2)システムコールがブロックする、とくにファイルにappendしていくタイプのwrite(2)がブロックするという前提で書く必要があるかという点については、ほとんど起きないレアなケースなので、普通のアプリケーションを書くときにとくに意識する必要はないと思います。

一方で、例えばJVMのsafepointの中のような、ブロックしてしまうとアプリケーション全体に対してクリティカルな影響を与え得るような場所においては、気をつけてコードを書く必要がある、というのが得られた学びです。

以上になります。ありがとうございました。

（会場拍手）