1秒から10ミリ秒：API GatewayにおけるPrometheusの遅延削減

1～2秒の遅延を伴うリクエスト

APISIXコミュニティでは、ユーザーからある奇妙な現象が報告されています。通常にデプロイされたAPISIXクラスターにトラフィックリクエストが入ると、ごく少数のリクエストが1～2秒という異常に長い遅延を引き起こすというものです。ユーザーのQPSスケールは約10,000で、このような異常なリクエストは稀で、数分ごとに1～3回しか発生しません。

ユーザーは、高遅延リクエストのキャプチャをissueで提供しました。これらのスクリーンショットから、確かに高遅延のリクエストが存在し、一部は秒レベルに達していることがわかります。

High Latency Requests 1.png

High Latency Requests 2.png

この現象に伴って、もう一つ注目すべき現象があります。それは、ワーカープロセスの1つのCPU使用率が100%に達することです。

100% CPU.png

開発チームは、この現象が発生する条件を把握しました：

Prometheusプラグインが有効化されており、Prometheus ExporterがAPISIXのエンドポイント/apisix/prometheus/metricsにアクセスしてメトリクスを収集している。
Prometheusプラグインがカウントするメトリクスの数がある規模に達している。通常、数万レベル。

この現象は業界で**「ロングテールリクエスト」**と呼ばれています。これは、リクエストグループの中で、ほとんどのリクエストが正常な応答時間を持つのに対し、ごく少数のリクエストが異常に長いリクエスト時間を持つ状況を指します。これは、バックエンドシステムのパフォーマンスボトルネック、リソース不足、またはその他の理由による可能性があります。致命的なバグではありませんが、エンドユーザーの体験に深刻な影響を与えます。

問題の分解

APISIXは、オープンソースのLuaライブラリnginx-lua-prometheusに基づいて、Prometheusプラグインを開発し、メトリクスの追跡と収集機能を提供しています。Prometheus ExporterがAPISIXが公開するPrometheus指標のエンドポイントにアクセスすると、APISIXはnginx-lua-prometheusライブラリが提供する関数を呼び出して、メトリクスの計算結果を公開します。

開発チームは問題を特定しました。それは、nginx-lua-prometheusでメトリクス指標を公開するために使用される関数prometheus:metric_data()です。

しかし、これはあくまで予測であり、ロングテールリクエストがこれに関連していることを証明する直接的な証拠が必要です。また、以下の問題を明確にする必要があります：

この関数は具体的に何をしているのか？
なぜこの関数がロングテールリクエストを引き起こすのか？

開発チームは、問題を再現するためにローカル環境を構築しました。主に以下のシナリオをシミュレートしています：

シミュレートされたクライアントが、APISIXによってアップストリームにプロキシされる通常のリクエストを送信する。
Prometheus Exporterが5秒ごとに/apisix/prometheus/metricsにアクセスし、APISIXがprometheus:metric_data()関数を呼び出すことをシミュレートする。

再現環境：

Reproduced Environment.png

テストを実行する際、wrk2のテスト結果でP100やその他の指標を観察し、ロングテールリクエスト現象が存在するかどうかを確認しました。また、APISIXのフレームグラフを生成し、ロングテールリクエストが発生した際のCPU使用率を観察しました。

wrk2のテスト結果：

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
   50.000%    1.13ms
   75.000%    2.56ms
   90.000%    4.82ms
   99.000%   14.70ms
   99.900%   27.95ms
   99.990%   74.75ms
   99.999%  102.78ms
  100.000%  102.78ms

このテスト結果から、テスト中に99%のリクエストが14.70ミリ秒以内に完了し、ごく少数のリクエストが100ミリ秒以上かかることがわかります。また、メトリクスの数を変数として複数回テストを行い、メトリクスの数がP100の遅延と線形的に増加することを発見しました。メトリクスが100,000レベルに達すると、P100は秒レベルに達します。

生成されたフレームグラフ：

Flame Graph1.png

フレームグラフの関数スタックから、prometheus:metric_data()が最も長い水平幅を占めており、多くのCPUを消費していることが証明され、prometheus:metric_data()がロングテールリクエストを引き起こしていることが直接的に決定されます。

prometheus:metric_data()関数が何をしているのかを簡単に分析しましょう。

prometheus:metric_data()は、共有メモリからメトリクスを取得し、それらを分類し、Prometheus互換のテキスト形式に処理します。このプロセスでは、すべてのメトリクスが辞書順にソートされ、メトリクスのプレフィックスが正規表現で処理されます。経験則として、これらは非常にコストのかかる操作です。

不完全な最適化の試み

遅延を引き起こしたコードを特定したら、次のステップはフレームグラフを組み合わせてコードを詳細に分析し、最適化の余地を見つけることです。

フレームグラフから、fix_histogram_bucket_labels関数を特定しました。この関数をレビューすると、string:matchとstring:gusbという2つの敏感な関数が見つかりました。これらの2つの関数は、LuaJITによってJITコンパイルできません。それらはインタプリタで実行されるしかありません。

LuaJITは、Luaプログラミング言語のJITコンパイラで、Luaコードを機械語にコンパイルして実行できます。これにより、インタプリタを使用してLuaコードを実行するよりも高いパフォーマンスを提供できます。

LuaJITを使用してLuaコードを実行する利点の1つは、コードの実行速度を大幅に向上させることができることです。これにより、APISIXは大量のリクエストを処理する際に低遅延を維持し、高並列環境でより良いパフォーマンスを発揮できます。

したがって、LuaJITがコンパイルできないコードは、潜在的なパフォーマンスボトルネックになります。

上記の情報をまとめ、nginx-lua-prometheusにissue: optimize the long tail request phenomenonを提出し、このプロジェクトの作者であるKnyarと連絡を取り、最適化できるスペースを探りました。Knyarは迅速に応答し、最適化できる場所を明確にしました。そこで、PRを提出しました：chore: use ngx.re.match instead of string match to improve performance。

このPRでは、主に以下を完了しました：

string:matchの代わりにngx.re.matchを使用
string:gusbをngx.re.gsubに置き換え

この最適化を完了した後、これが改善するパフォーマンスは限定的であり、根本的な問題を解決できないことがわかります。根本的な問題は：

NGINXはマルチプロセスシングルスレッドアーキテクチャです。すべてのワーカープロセスはTCP（Transmission Control Protocol）接続を監視しますが、接続がワーカープロセスに入ると、他のワーカープロセスに移行して処理することはできません。

これは、ワーカープロセスが非常に忙しい場合、そのワーカープロセス内の他の接続がタイムリーに処理されない可能性があることを意味します。一方、プロセス内のシングルスレッドモデルは、すべてのCPU集約型およびIO集約型タスクが順次実行されなければならないことを意味します。タスクの実行に長時間かかる場合、他のタスクが無視され、タスク処理時間が不均一になる可能性があります。

prometheus:metric_data()は、計算のために大量のCPUタイムスライスを占有し、通常のリクエストを処理するためのCPUリソースを圧迫します。これが、ワーカープロセスのCPU使用率が100%になる理由です。

この問題に基づいて、上記の最適化を完了した後、さらに分析を続け、フレームグラフをキャプチャしました：

Flame Graph2.png

上記のフレームグラフbuiltin#100は、luajit/luaライブラリ関数（string.findなど）を表しています。これは、https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua で対応する関数名を取得できます。

使用方法：

$ luajit ljff.lua 100
FastFunc table.sort

メトリクスの計算が過剰なCPUを占有するため、メトリクスを計算する際にCPUタイムスライスを放棄することを検討します。

APISIXにとって、通常のリクエストを処理する優先度が最も高く、CPUリソースはこれに傾けるべきです。同時に、prometheus:metric_data()はPrometheus Exporterのメトリクスを取得する効率にのみ影響します。

OpenRestyの世界には、CPUタイムスライスを放棄する隠れた方法があります：ngx.sleep(0)です。このメソッドをprometheus:metric_data()に導入します。メトリクスを処理する際、一定数のメトリクス（例えば200メトリクス）を処理した後にCPUタイムスライスを放棄し、新しいリクエストが処理される機会を与えます。

この最適化のためにPRを提出しました：feat: performance optimization。

私たちのテストシナリオでは、メトリクスの総数が100,000レベルに達した場合、この最適化を導入する前にwrk2でテストした結果：

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%   10.21ms
 75.000%   12.03ms
 90.000%   13.25ms
 99.000%   92.80ms
 99.900%  926.72ms
 99.990%  932.86ms
 99.999%  934.40ms
100.000%  934.91ms

最適化後のwrk2結果：

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%    4.34ms
 75.000%   12.81ms
 90.000%   16.12ms
 99.000%   82.75ms
 99.900%  246.91ms
 99.990%  349.44ms
 99.999%  390.40ms
100.000%  397.31ms

P100指標は、最適化前の約1/3から1/2です。

しかし、これでもこの問題を完全に解決することはできません。最適化後のフレームグラフを分析すると：

Flame Graph After Optimization.png

builtin#100（table.sort）とbuiltin#92（string.format）が依然として水平軸のかなりの幅を占めていることがわかります。これは：

prometheus:metric_data()は最初にtable.sortを呼び出してすべてのメトリクスをソートします。メトリクスが100,000レベルに達すると、100,000の文字列をソートすることに相当し、table.sortはngx.sleep(0)によって中断できません。
string.formatとfix_histogram_bucket_labelsが使用される場所は最適化できません。knyarとコミュニケーションを取った結果、これらのステップはprometheus:metric_data()が正しい形式のメトリクスを生成するために必要であることがわかりました。

これまでのところ、コードレベルの最適化方法は尽くされましたが、残念ながら問題はまだ完全に解決されていません。P100のメトリクスにはまだ顕著な遅延があります。

どうするか？

核心的な問題に戻りましょう：prometheus:metric_data()が大量のCPUタイムスライスを占有し、通常のリクエストを処理するためのCPUリソースを圧迫しています。

Linuxシステムでは、CPUが割り当てるタイムスライスはスレッドまたはプロセスですか？正確にはスレッドであり、スレッドが実際の作業単位です。しかし、NGINXはマルチプロセスシングルスレッドアーキテクチャで、各プロセスには1つのスレッドしかありません。

この時点で、私たちは最適化の方向性を考えました：prometheus:metric_data()を他のスレッド（より正確にはプロセス）に移動することです。そこで、2つの方向性を調査しました：

ngx.run_worker_threadを使用してprometheus:metric_data()の計算タスクを実行し、CPU集約型タスクをスレッドプールに委譲する。
別のプロセスを使用してprometheus:metric_data()の計算タスクを処理し、このプロセスは通常のリクエストを処理しない。

PoC（proof of concept）を行った後、オプション1を拒否し、オプション2を採用しました。オプション1は、ngx.run_worker_threadがリクエストに依存しない計算タスクを実行するのに適しているため、prometheus:metric_data()はリクエストに関連しているため拒否されました。

オプション2の実装：privileged agent（特権プロセス）にprometheus:metric_data()を処理させます。しかし、特権プロセスはどのポートもリッスンせず、どのリクエストも処理しません。したがって、特権プロセスを変更してポートをリッスンできるようにする必要があります。

最終的に、feat: allow privileged agent to listen portとfeat(prometheus): support collect metrics works in the privileged agentを使用してオプション2を実装しました。

この最適化を適用したAPISIXを使用してテストを行い、P100の指標遅延が合理的な範囲に減少し、ロングテールリクエストの問題が存在しなくなったことを確認しました。

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 50.000%    3.74ms
 75.000%    4.66ms
 90.000%    5.77ms
 99.000%    9.99ms
 99.900%   13.41ms
 99.990%   16.77ms
 99.999%   18.38ms
100.000%   18.40ms

これは繊細な解決策であり、核心的な問題を解決します。私たちはこの解決策を本番環境で観察し、検証しました。ロングテールリクエスト現象を排除し、追加の例外を引き起こしませんでした。

まとめ

この問題を修正している際に、新しい考えが浮かびました：オープンソースライブラリnginx-lua-prometheusはAPISIXに適しているのか？

私たちはAPISIX側でprometheus:metric_data()の問題を解決しました。同時に、nginx-lua-prometheusの他の問題も発見し、修正しました。例えば、fix memory leakやLRU cache eliminationなどです。

nginx-lua-prometheusはもともとNGINX向けに設計されており、OpenRestyやOpenRestyベースのアプリケーション向けではありません。しかし、OpenRestyエコシステムでPrometheusエコシステムに接続するより成熟したオープンソースプロジェクトはnginx-lua-prometheus以外にありません。そのため、nginx-lua-prometheusはOpenRestyエコシステムのためにオープンソースコミュニティによって常に推進されてきました。

おそらく、APISIXのソースコードを変更せずにPrometheusエコシステムに接続する方法をさらに探求する必要があります。例えば、APISIXに適した依存ライブラリを設計するか、Prometheusエコシステムの成熟したプロジェクトに何らかの方法で接続し、メトリクスの収集と計算のプロセスをそれらの成熟したプロジェクトに移行する方法を模索する必要があります。