search infra teamのmrkm4ntrです。我々のチームではElasticsearchをKubernetes上で多数運用しています。歴史的経緯によりElasticsearchのクラスタは全てElasticsearchクラスタ専用のnode pool上で動作していました。ElasticsearchのPodは使用するリソースが大きいため、このnode poolのbin packingが難しくコストを最適化できないという問題がありました。そこで全てのElasticsearchクラスタを専用のnode poolから他のワークロードと共存可能なnode poolへ移行しました。ほとんどのクラスタが問題なく移行できたのですが、唯一移行後にlatencyのスパイクが多発してしまうものがありました。
この記事では、その原因を調査する方法と発見した解消方法について説明します。
発生した現象
共用node poolへ移行後にピーク時間帯において95pのlatencyが下図の青線のようにスパイクしました。
一旦このクラスタを専用node poolに戻すと、latencyは元どおりに落ち着きました。各メトリクスを見てもsearch thread poolのキューのサイズが上がっている他は特に怪しいものは見当たりません。CPUやmemoryのリソースが不足しているわけでもありません。search thread poolのキューのサイズが上がっているのはlatencyが上がったことによりキューのサイズが上がったと考えられるため原因ではなく結果だと思われます。該当クラスタのElasticsearchのversionは7.10.2でした。
プロファイラの利用
メトリクスを見ても原因がわからなかったため、プロファイラを使ってflame graphを表示することにしました。まずはkube-flame (https://github.com/yahoo/kubectl-flame )を使ってJVMのprofilerであるasync-profiler (https://github.com/async-profiler/async-profiler )を動かします。以下が得られたflame graphです。
Elasticsearchの検索処理にはquery phaseとfetch phaseという二つのphaseがあり、query phaseでは各シャードにて転置インデックスを使って検索処理を行い、実際にヒットしたドキュメントのidのリストを取得します。一方fetch phaseではそのドキュメントのfieldを取得します。上のflame graphからはこのクラスタにおいてはfetch phaseが支配的ということがわかります。多くの場合はquery phaseが支配的になるため少々特殊な使用方法です。
何度かプロファイラを動かすと怪しそうなグラフが取得できました。
黄色の箇所をズームするとCPUがNativeThreadSetのaddとremoveにおいてスピンロックを取得しようとしていることがわかります。
下記の syncrhonized(this)の箇所ですね。
https://github.com/AdoptOpenJDK/openjdk-jdk15u/blob/49dc2dfcefa493a9143483e11144343e83038877/src/java.base/share/classes/sun/nio/ch/NativeThreadSet.java#L50
https://github.com/AdoptOpenJDK/openjdk-jdk15u/blob/49dc2dfcefa493a9143483e11144343e83038877/src/java.base/share/classes/sun/nio/ch/NativeThreadSet.java#L75
とはいえこのコード自体におかしいところはありません。
ここで調査が暗礁に乗り上げるかと思われましたが、async-profilerについて調べている際にLINEヤフー社のKafkaチームの方が発表された下記の資料を見つけました。
https://speakerdeck.com/line_developers/time-travel-stack-trace-analysis-with-async-profiler
こちらによるとasync-profilerによって出力されるJFRファイルを基に、各threadが各時点において何のメソッドを実行していたのかを可視化するツール(https://github.com/ocadaruma/jfrv )を作って公開されたそうです。
早速async-profilerにJFR形式で出力させ、jfrvで読み込んでみました。
NativeThreadSetでフィルタリングした結果、確かにlatencyのスパイクが発生した時点でNativeThreadSetのaddやremoveがロックを待機しています。
次はこれらのメソッドを呼び出している箇所でlatencyのスパイク中に出現回数が上がったものを探します。以下のとおり、LuceneのDataInputクラスのskipBytesというメソッドが見つかりました。
これはElasticsearchのドキュメントの_sourceが入っているLZ4圧縮されたLuceneのStoredFieldを読み込む際に呼び出されています。
https://github.com/apache/lucene-solr/blob/2dc63e901c60cda27ef3b744bc554f1481b3b067/lucene/core/src/java/org/apache/lucene/codecs/lucene87/LZ4WithPresetDictCompressionMode.java#L110-L118
ではなぜこのメソッドの出現回数が増加したのでしょうか？この現象が発生する直前に下図のように大きなmerge処理が走り、refreshによってそれが検索可能になったことがわかります。
Elasticsearchにおいて新しく追加されたデータは、refreshによってセグメントと呼ばれるファイル(実際はpage cacheですが)に書き出されます。これらのファイルはimmutableであり、小さなセグメントがrefreshのたびに新しく次々に書き出されるのですが、バックグラウンドで複数のセグメントはmergeされ、新しく大きなセグメントとして書き出されます。このクラスタではインデックスは新しい順でソートされており、基本的にクエリにヒットするのは新しく追加されたばかりの小さなセグメントに入っているドキュメントでした。
ここで仮に新しく追加されたばかりのセグメントが、大きなセグメントにmergeされた場合を考えてみます。その場合、query phaseではインデックスはソートされているためlatencyは変わらないでしょう。しかし、fetch phaseではLZ4の辞書の後ろに_sourceが格納されているため、大きなセグメントでは辞書も大きくなり、ヒットしたドキュメントの_sourceを取得するためには毎回大きな辞書の分をskipする必要がでてきます。skipBytesは内部で1024バイトずつループでskipするため，これがskipBytesの出現回数を増やす原因だと考えました。
MergePolicyのパラメータ変更
Elasticsearchでは、LuceneのTieredMergePolicyというmerge policyを用いてどのセグメントをmergeするべきかどうかを選んでいます。このmerge policyではmergeするセグメントのサイズの差をskewという尺度で定義し、そのskewが小さいものを選択します。つまり基本的には上記のようなmergeはほとんど起きないはずです。
TieredMergeのパラメータを調べたところ、 floor_segmentと max_merge_at_onceというものを見つけました。前者はskewを計算する際にその値よりも小さいセグメントを floor_segmentの値まで切り上げて計算するというもので、後者はその名のとおり一度にmergeできるセグメントの最大数を表します。
新しく追加されたセグメントが floor_segmentより小さかった場合、 floor_segment(デフォルト値は2MB)のサイズとして計算されるため、より大きなセグメントにmergeされる可能性が上がってしまいます。またskew計算時の分母はmerge後のトータルサイズなので max_merge_at_onceが大きければ小さいセグメントと大きいセグメントを含んだmergeのskewがあまり大きくならない可能性があり、そのようなmergeが選択されてしまう可能性が上がります。そこでこれらのパラメータの値を小さな値に変更することとしました。結果が下図です。
破線が変更前である前日のもの、実線が変更後です。見てのとおりスパイクが綺麗になくなっています。仮説が正しかったであろうことがわかりました。
DataInputのskipBytesの詳細
NativeThreadSetのaddとremoveはJVMからpread64システムコールを呼ぶ際に使われています。DataInputのskipBytesは不要な箇所をスキップするためにpread64で読んだものを捨てるという処理を実行しています。_sourceが格納されているStoredFieldのファイルはmemory mappedファイルなので不要な場所をスキップするためにファイルを読む必要など全くなく、現在のアドレスを加算するだけで事足りるはずです。実はこの修正は既にLuceneに入っており、Elasticsearchのv8以降にはその実装が使われています。
https://github.com/apache/lucene/commit/84a35dfaea27581174c1104e239187112a1b5d43
可能な限りElasticsearch v8を使いましょう。
先ほどはfetch phaseでパフォーマンス問題が発生する話でしたが、別のElasticsearch v7を使っているクラスタではquery phaseにおいてDataInputのskipBytesによりパフォーマンスが悪化する現象が起きていました。DataInputのskipBytesは転置インデックスのposting listをskipする際にも使われています。該当のクラスタのインデックスにはstatusがon_saleのものしか入っていなかったのですが、クエリのfilterにstatus=on_saleが指定されていました。これは全てのドキュメントが入っているposting listをスキャンすることを意味しますが、posting listはスキップリストで実装されているためそれほど高コストではないはずです(勿論ないに越したことはないですが)。ところがskipBytesはpread64を何度も呼ぶため非常に高コストな処理となってしまっていました。そこでstatus=on_saleのfilterをクエリから削除するとlatencyが以下のように劇的に改善しました。
さいごに
この記事ではJVMのプロファイラを用いてElasticsearchのlatencyのスパイクの原因を調査する方法と発見した原因とその対処法について述べました。jfrvを使って必要な部分のみ抜き出したflame graphは眺めていると色々な発見があり、またソースコードリーディングにも役立つのでおすすめです。
またlatencyスパイクの原因となったmergeについては発見できましたが、共用node poolに移行すると望ましくないmergeが発生する具体的な原因についてはまだ特定できていないので、今後究明していきたいと思います。
さいごにjfrvという素晴らしいツールを公開してくださったocadarumaさん(https://github.com/ocadaruma )ありがとうございました！
