Apache Kafkaのトラブルシューティングに見る、LINEが“根本的な”原因究明を大切にする理由

トラブルの根本的な解決策を探す

河村勇人氏：さて、ここからはもう1つのトピック、トラブルシューティングについて話をしたいと思います。

ここまでお話ししたように、我々は日々多くの時間を費やして我々のプラットフォームに対してリライアビリティエンジニアリングを行っているのですが、それでもトラブルは起きるときには起きてしまいます。

もう一度繰り返すのですが、非常に大きなスケールのトラフィックと高いサービスのrequirementというのは、組み合わさったときにはトラブルの宝庫になります。実際にトラブルが起きてしまったときに最後の違いを作るのは何かというと、私はそれに対して臨むスタンスだと思っています。

我々のチームでは、トラブルが起きたとき、常に根本的な解決を追究することを是としています。これはどういうことかというと、例えば、KafkaのBrokerでGCの問題がありました。ある人は、JVMのパラメータを少しずついじりながらGCのパフォーマンスがどう変わるかを見てみて、改善が見られたところで「これぐらいでいいか」というところを落としどころにすると思います。これはワークアラウンドです。

一方で、ある人は、そもそもなぜGCの問題が起きているのかを、原因からその結果に至るまで因果関係をすべてクリアにして、対策を考えると思います。我々のチームでは常にこの後者を追究します。

このような根本的な問題の解決がワークアラウンドよりもよいと考える理由は、いくつかあります。

まず、このような方法を通じて根本的にクリアにされた問題とその解決は、その過程で得られる知識や経験が蓄積して、将来にわたって役に立ちます。また、ここで考えられた解決策は、同じようなドメインの少し違う問題に対して、非常に高い応用性があります。そして最後に、このような過程を経て考えられた根本的な解決策は非常に持続性があって、状態を恒久的に改善します。

実際にこの考え方に基づいて行われたトラブルシューティングの事例を紹介したいと思います。

トラブルシューティングの実例

まず最初に我々が観測した症状は、我々のクラスタにおける重要なAPIの99パーセンタイルのレスポンスタイムが10秒を超える、非常に悪化をしているということでした。これは先ほどお見せした我々のSLOを大きく超過してしまっています。

また、この問題が起きた際には、稀にですが、この問題が起きたBrokerがZooKeeperのセッションをタイムアウトして、クラスタから抜けてしまうということが起きていました。これがもし2つのBrokerで同時に発生すると、2つのBrokerが同時にクラスタから抜ける、つまりレプリカが同時に2つ減ってしまうことになるので、これはその時点で障害になってしまいます。

ということで、非常にクリティカルな問題として調査を開始しました。

調査を始めると、いくつか観測が得られました。まず最初に見つかったのは、スレッドのutilizationが上がっていることです。Kafkaはリクエストを処理するためのスレッドプールを内部にいくつか持っているのですが、それらでutilizationの増加が見られました。

今このグラフが示しているのは各スレッドのアイドルタイム。つまり、utilizationはこれの逆になるのですが、ご覧のように、すべてのスレッドでutilizationが上がっているのがわかると思います。

また、もう1つ見つかったこととしては、Kafkaが動いているJVM、Brokerが動いているJVMにおいて、JVMのpause timeが非常に伸びていることがわかりました。我々は日々いわゆるGC問題に備えてJVMのpause timeのメトリックやログを取得しているのですが、それらに増加が見られました。

とくにおもしろいのはこのログのほうで、これはJVMのpause timeについて少し詳細な情報を見せているログなのですが、これを見てみると、前半の「Application Threads Were Stopped」という部分に1秒を超える増加が見られるのに加えて、後半部分の「Stopping Threads Took」という部分、こちらも同じように増えていることがわかります。これはあまり見られないパターンです。

問題の解決策の仮説を立てる

どういった場合にこの現象が起きるのかを理解するために、JVMについて少し勉強する必要がありました。「async-profiler」という非常に有名なJVMのプロファイリングツールを開発されている方がブログに非常に良い解説を書かれているので、そこから少し引用したいと思います。

JVMにはsafepointというコンセプトがあります。safepointというのは、JVMがGCやjstackといったクリティカルなオペレーションを実行するために、すべてのアプリケーションスレッドを停止する必要がありますが、この全アプリケーションスレッドが停止している状態のことをsafepointといいます。

また、このsafepointに入るためにJVMはsafepoint flagというものをオンにします。このsafepoint flagがオンにされたことによって各アプリケーションスレッドが協調して、自律的に停止状態に入るわけですが、このflagがオンになってから一つひとつアプリケーションスレッドが止まっていって、最終的にすべて止まりきるまで、この時間のことをsafepoint syncと呼びたいと思います。

先ほどのログで増えていた部分は、この後半部分、safepoint syncのほうが増えていたということなんですね。なので、この時点でこれが普通のGC問題ではないことがわかりました。

そして、追加で調査を継続していると、もう1つわかったことがありました。それは、この問題が起きていた時間帯に、そのBrokerが動いてたマシンにおいてディスクのアクセスタイムが非常に伸びていたということです。

さて、ここまでわかった2つの事実を合わせながら少し想像を働かせてみると、1つ仮説ができあがります。それは、JVMがsafepointの中においてなにかしらのディスクアクセスをしていて、そこで発生した遅いIOがsafepoint全体の時間を延ばしているのではないかという仮説です。

実際にJVMのコード、OpenJDKのコードを読んでみたところ、safepointの中からGCログを書いていることがわかりました。

SystemTapを用いて疑問点を検証

ただ、ここで1つ疑問が湧きます。JVMがGCログを書き出すために使っているwrite(2)というシステムコールがあります。このシステムコールは果たしてブロックするのかという疑問です。

これは一般的には、多くの場合、IO待ちではブロックしないことが知られています。

なぜかというと、Linuxカーネルにおいてwrite(2)システムコールがやることは、書き出したいデータをカーネル内部のpageというデータにコピーをして、このpageのdirty flagをオンにするだけなんですね。

そして、そのdirty flagがオンになったpageについて、カーネルの別のタスクであるwritebackタスクが定期的にそのデータをディスクにフラッシュして、dirty flagを降ろす、というのが一般的なLinuxにおけるdisk writeの動作モデルです。

なので、write(2)を呼び出すのは基本的にはメモリコピーだけで済むはずであって、IOでブロックするはずはないと思っていたわけです。

しかし、依然としてやはりwrite(2)が怪しいということで、write(2)システムコールの実行時間を調べてみることにしました。

ここで用いたのはSystemTapというツールです。SystemTapは、ダイナミックトレーシングツールと呼ばれるもので、右側に示されているような数行のスクリプトを書くことによって、Linuxカーネルの内部で起きるさまざまなイベントやアクティビティについて観測できるようになる、非常に強力なツールです。

これを用いてwrite(2)システムコールの実行時間を調べてみました。すると、実際に2秒以上かかっているケースが見つかりました。このオレンジでハイライトされているところに注目してほしいのですが、実行時間が2,843ms。3秒弱ですね。

そして、そのときwrite(2)システムコールを呼び出していたアプリケーションのバックトレースも同時に取得しているのですが、ご覧のようにJVMのsafepointの中からそれが呼び出されていることがわかります。

ということで、我々の大きな前提がここで崩れてしまいました。write(2)システムコールはブロックしないと思っていたのですが、することもある、ということがわかったわけです。

原因究明の最中に起きた2つの問題

では、我々はこの時点で解決策を考える準備ができたか？　私はまだだと思うわけです。繰り返すのですが、根本的な解決は根本的な原因の究明から生まれると思います。我々はまだなぜwrite(2)システムコールがブロックしてしまうのかを理解していません。ということで、調査を継続しました。

なのですが、ここで2つほど問題が起きます。

1つは、実はこの問題が起きていたマシンはまだサービスで使っていて、Kafka Brokerが動いていたんですね。ですが、おそらくハードウェアの故障率が上がってきたことによって、この問題の発生頻度が非常に増えてしまって、サービスレベルに対して与える影響が許容できないレベルになりました。なので、このマシンをサービスアウトする必要がありました。

また、サービスアウトしたあと、継続してそのマシンの上で実験を繰り返していたのですが、私の使ったスクリプトが何度かこのマシンのカーネルをクラッシュさせてしまって、インフラチームのほうに「ハードリブートしてください」とお願いをしていたんですね。そのうちの1回で、ハードリブートをお願いして返ってきたときに、インフラチームの人から「ディスクが壊れていたので交換しておきましたよ」と言われました。

私はこれにドキッとして嫌な予感がしたのですが、問題を再現するはずのスクリプトを動かしてみたら、案の定、再現しなくなっていました。ハードウェアを交換してもらったことによって、問題の再現環境を失ってしまったわけですね。

では、これ諦めるかというと、諦めません。今私たちが再現しなければいけないことは2つあります。1つはBrokerが動いていたときに発生していたwrite(2)のワークロード。もう1つは遅くなっているディスクです。

Brokerのwrite(2)のワークロードのほうを再現するのは非常に簡単で、ご覧のような非常にシンプルなCのプログラムを書きました。ファイルをオープンして、ループの中でwrite(2)を呼び出す。それだけです。

難しいのは、遅くなっているディスクを再現するほうですね。これはwrite(2)システムコール自体を遅くするのとはわけが違います。write(2)システムコールはユーザースペースとカーネルの間にあるインターフェースのレイヤーなので、これを挿し替えることは比較的簡単なのですが、今知りたいのはwrite(2)の下で何が起きているのかということです。

では、遅くなっているディスクを再現するためにどうすればいいかなと考えたのち、1つ思いついたのは……Linuxカーネルの中にgeneric_make_requestというファンクションがあります。これはカーネルの中で実際のディスクデバイスに対してIOのリクエストを発行するために利用されているゲートウェイのようなファンクションなのですが、この処理をフックしてそこに意図的なディレイを挿し込めないかということを考えました。

カーネルモジュールを書いて問題を再現

最初に、またSystemTapを使って、generic_make_requestの処理をフックして、その中で少し重い処理を回すことによって意図的なディレイを入れられないかと試したのですが、これはうまくいきませんでした。

SystemTapはそもそもオーバーヘッドに対して安全にカーネル内のインスペクトができるようにデザインされているツールです。なので、オーバーヘッドが一定のレベルを上回ったときには自発的に停止するようなセーフティが組み込まれていました。ということで、これはうまくいきませんでした。

少し方法を思案したのち思いついたのは別の方法です。「kprobe」というLinuxカーネルに提供されているAPIがあります。これは、Linuxカーネル内の任意のファンクションについて、その処理をフックすることができるAPIです。そして、SystemTapも実はバックエンドとしてこのAPIを用いています。このAPIを直接用いてLinuxカーネルのモジュールを自分で書き、それを使うという方法を思いつきました。

これは実際のそのモジュールのコードなのですが、詳しくは見ません。ただ、上から少しだけ見てみると、generic_make_requestというファンクションについて、kprobeのフックをregisterします。そして、そのハンドラーの中で発行されようとしているIOのリクエストについて、そのタイプとフラグを見つつ、サンプリングしながら300msディレイを入れるという処理をしています。

実際にこれを動かしてみたところ、問題が再現できました。また、その問題が再現したときにgeneric_make_requestを呼び出していたタスクのバックトレースも取得できました。そうすると、我々ext4というファイルシステムを使っていたのですが、このext4のジャーナリングを行っているタスク、それがここで詰まっていることがわかりました。

なのですが、我々はまだ、なぜここでext4のジャーナリングタスクが詰まると、それがwrite(2)を呼び出しているアプリケーションにまで波及するのかが説明できなかったんですね。なので、少し方法を変えてみました。

別方向からのアプローチ

今度は別方向からのアプローチとして、write(2)というシステムコールが内部でさまざまなファンクションを呼んでいます。その下にコールグラフが展開されているのですが、その中のどの部分で多くの時間を費やしているのかを調べてみることにしました。ここで用いたのもまたSystemTapなのですが、怪しいと思われるファンクションを一つひとつその調査の対象に加えながら、実行時間を計測するということをしました。

非常に地道な作業なのですが、全部で14回、このように怪しいところを一つひとつ追加しながらやってみたところ、最終的に求めた結果が得られました。

今度は下から上に向かって読む必要があるのですが、vfs_writeというファンクションの数段下で呼ばれている__lock_page。これはpageという先ほどお話ししたデータのlockを取るためのファンクションなのですが、ここで実行時間の大半が費やされていることがわかりました。

ここまでわかってしまえば、あとやるべきことは、いわゆる lock contentionの解析というもので、このlockを誰が持っているのかを解析する必要があるわけです。ここで使ったテクニックも話としては非常におもしろいのですが、今日は、時間の都合上、割愛したいと思います。

いわゆる lock contentionの解析をした結果、最終的にこのような3段階の依存構造がわかりました。

write(2)を呼び出しているアプリケーション、これがpageのlockを取ろうとするのですが、そのlockはすでにカーネルの別のタスク、writebackタスクというものが取得しています。そして、このwritebackタスクも、ext4のジャーナリングタスクが状態を管理しているバッファが書き込み可能な状態になるのを待って、ブロックしている。という依存構造がわかったわけです。

最終的な問題の全体像を表したのがこの図になるのですが、少しこれは大きすぎるので、各部分をフォーカスしながら見ていきたいと思います。

問題の全容と解決策

まず、Kafkaが動いているJVMがあります。そのJVMがGCやjstackなどのsafepointオペレーションを実行するために、safepoint flagをオンにします。そして、それに対してアプリケーションスレッドが協調的に停止状態に入ります。すべてのアプリケーションスレッドが停止したあと、JVMのVMスレッドがGCやjstackなどのオペレーションを実行して、そこでの記録をログとして書き出します。ここでwrite(2)システムコールが呼ばれます。

今度は処理がカーネルの内部に移って、write(2)システムコールは書き込むpageのlockを取ろうとするのですが、このpageのlockはすでに別のタスクが保持しています。カーネルのwritebackタスクです。

そして、このwritebackタスクも、別のjournal_headというデータがありますが、これの状態が書き込み可能になるのを待って、ここでブロックしてしまっています。

では、このjournal_headというデータの状態を誰が管理しているかというと、ext4のジャーナリングタスクです。ジャーナリングタスクは、このjournal_headの状態を書き込み不可の状態に保ちながら、実際のデバイスに対してIOを発行して、その結果を待っています。

そして、今回の問題の根本は、このディスクデバイスが故障していたことによってレスポンスタイムが悪くなり、それによってこの部分（スライドのgeneric_make_requestからIO completeの間を指して）の時間が伸びているのがだんだんと波及していって、最終的にJVMのsafepointの時間が伸びているというのが問題の全容でした。

そして、後半の実験においては、このディスクに対してIOリクエストを発行するgeneric_make_request、この部分をフックして意図的なディレイを挿入することで問題を再現しました。というのがここまでの話でした。

さて、これで原因がすべてクリアになったので、我々は解決策を考える準備ができました。ここまでわかってしまえば、解決策としては非常にシンプルで、2つ考えられると思います。

1つは、ext4以外のファイルシステムを使う、ないし、ext4のジャーナリングを切る方法です。もう1つの方法としては、tmpfs、いわゆるインメモリファイルシステムを用いて、そこにまず第1のストレージとしてGCログを書き込みながら、そのリアルタイムなバックアップを、実際のディスクの領域に対して、別のプロセスから取るような方法です。

両方とも実験で有効性を証明した上で、プロダクションに適用しました。

最も信頼されるミドルウェアプラットフォームへ

ということで、今日の私の話、全体の話をまとめたいと思うのですが、今日は、我々の考えるリライアビリティエンジニアリング、その役割や責任範囲、またはその実践に関する話をしました。

そのうちの1つとして、SLIの計測、そしてビジュアライゼーションにおいては、クライアント側からの視点で計測をすることが非常に重要であるという話をしました。Kafkaのような分散システムにおいては、サーバとクライアントは協調して動作をするために、必ずクライアントの視点からシステム全体のサービスレベルを測る必要があります。

また、トラブルシューティングや最適化、またそこから発生する予防的なエンジニアリングにおいては、常に根本的な原因の究明と、そこから生まれる解決を追究しているという話をしました。

そうするモチベーションの1つとして、そこで得られた知識や経験は蓄積して将来にわたって役に立つという話をしたと思うのですが、実際に、今回この調査の過程で役立てられた知識は、今回新たに獲得したものがすべてではないんですね。

過去にKAFKA-4614やKAFKA-7504といった、これらはKafkaのupstreamにもコントリビュートされているKafkaのパフォーマンスの最適化に関する取り組みなのですが、こういったことを調査する過程で得た、JVMがGCを処理している過程で透過的に発生するIOがパフォーマンスにどのように影響するかといった知識や、read(2)やwrite(2)といったシステムコールはブロックするのか・しないのか、どのようなときにブロックしえるのかといった知識を活用しています。

また、今回この調査を通して新たにJVMのsafepointはどのように実装されているかといったことや、今まで知らなかったLinuxカーネルの新たな領域に関する知識も獲得しました。これらを活用して、次にまた別の問題が起きたときには今回よりももっと速く、その次に別の問題が起きたときにはさらに効率的に、原因の究明と問題の解決ができると思います。

そして、こういった徹底したスタンスでのエンジニアリングをこれまでずっと積み重ねてきた結果として、今日、LINEの中における最も信頼されるミドルウェアプラットフォームの1つとしての、我々のKafkaプラットフォームがあると思っています。

以上で、私の話を終わりたいと思います。ありがとうございました。

（会場拍手）