Nginx 正規表現のパフォーマンス：動的トレーシングで遅いパターンを特定

OpenResty XRay がどのようにしてアプリケーションの問題特定と効率化を支援するかをご覧ください。

詳細はこちら LIVE DEMO

Nginx や OpenResty で実行される遅い PCRE 正規表現は、気づかないうちに CPU コアを使い切ってしまうことがあります。本記事の事例では、(?:.*)*css という 1 つのパターンが、破滅的なバックトラッキング（catastrophic backtracking）により 1 回のマッチで最大 20.6 ミリ秒を記録しました。OpenResty XRay の動的トレーシングアナライザが稼働中のプロセスからこの原因を特定し、修正後のレイテンシは 59 マイクロ秒まで短縮されました。コードの計装やプラグインは一切不要です。

本記事では、診断の全プロセスを解説します：C 言語レベル・Lua レベルの CPU フレームグラフによるボトルネックの絞り込み、lj-slowest-ngx-re アナライザによる正規表現パターンの実行時間ランキング、lua_regex_match_limit による安全策、そしてバックトラッキングを行わない代替エンジンの紹介です。

前提条件とセットアップ

ここでは、RedHat Enterprise Linux 7 システムを例として使用します。OpenResty XRay がサポートする Ubuntu、Debian、Fedora、Rocky、Alpine などの Linux ディストリビューションであれば、同様に問題なく動作するはずです。

対象アプリケーションとして、オープンソースの OpenResty バイナリビルドを使用します。 既存の OpenResty や Nginx のバイナリ（自身でコンパイルしたものも含む）を使用することができます。 既存のサーバーインストールやプロセスに特別なビルドオプション、プラグイン、ライブラリは必要ありません。これこそが 動的トレーシング 技術の大きな利点であり、真に非侵入型のアプローチとなっています。

また、同じシステム上で OpenResty XRay の Agent デーモンを実行し、openresty-xray-cli パッケージからコマンドラインユーティリティを インストールして設定 しています。

CPU 使用率 100% のサンプル Nginx アプリケーション

サーバーで CPU 使用率が 100% に達する非効率的な OpenResty/Nginx Lua アプリケーションがあります。これは top コマンドラインユーティリティで確認できます：

$ top -p 3584441
...
    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
3584441 nobody    20   0   41284   7184   4936 R 100.0   0.0   1:43.97 nginx

Nginx プロセスの CPU 使用率が 100.0% であり、その PID が 3584441 であることにご注目ください。この PID は、後の動的トレーシング分析で参照します。

CPU フレームグラフによる遅い正規表現の特定

C 言語レベルの CPU フレームグラフ

CPU 使用率が高い C/C++ プロセス（Nginx プロセスを含む）を分析するには、まずそのプロセスから C 言語レベルの CPU フレームグラフ¹を取得する必要があります。OpenResty XRay は OpenResty/Nginx アプリケーションを自動的に検出し、サンプリングして様々な種類のフレームグラフを生成できますが、ここでは説明のために、コマンドラインユーティリティを手動で実行する方法を使用します。

$ orxray analyzer run lj-c-on-cpu -p 3584441
Start tracing...
Go to https://x5vrki.xray.openresty.com/targets/68/history/664712 for charts.

Nginx ワーカープロセスの PID を指定するために -p オプションを使用します。そして、標準的な OpenResty XRay ツールである lj-c-on-cpu を実行します。ここでは、より汎用的な c-on-cpu ツールは使用しません。なぜなら、前者は LuaJIT と PCRE の Just-in-Time (JIT) コンパイラからの動的マシンコードフレームを自動的に展開できるからです。

この C 言語レベルの CPU フレームグラフから、以下のことが分かります：

1. ほぼすべての CPU 時間が Lua コードの実行に費やされています（フレームグラフ内の ngx_http_lua_run_thread C 関数フレームがハイライトされていることに注目してください）。
2. また、Lua コードは PCRE マッチャーも実行しています（グラフ内の pcre_exec 関数フレームに注目してください）。
3. さらに、PCRE の JIT コードが実行されていることがわかります（グラフ内の _pcre_jit_exec 関数フレームから）。

この動的トレーシングツールの強力さに注目してください。対象アプリケーションからの助けを借りずに、JIT コードフレームを透過的に展開できます²。

次のステップは、Lua レベルの CPU フレームグラフのサンプリングと生成です。これにより、Lua コード内で何が起こっているかを確認することができます。

Lua レベルの CPU フレームグラフ

Lua レベルの CPU フレームグラフを生成するには、標準アナライザである lj-lua-on-cpu を以下のように使用します：

$ orxray analyzer run lj-lua-on-cpu -p 3584441
Start tracing...
Go to https://x5vrki.xray.openresty.com/targets/68/history/664870 for charts.

Lua レベルのフレームグラフは、JIT コンパイルされた Lua コードも表示します。これは、グラフ内の trace#3:regex.lua:721 フレームからわかります。これは、トレース ID 3 の LuaJIT トレースオブジェクトが、ソースファイル regex.lua の 721 行目の Lua コードから開始されていることを意味します。ほぼすべての CPU 時間が単一の Lua コードパスに費やされていることがわかります。この支配的な Lua コードパスの中で最も興味深い Lua 関数フレームは regex.lua:re_match です。その Lua ファイルには以下の記述があります：

local re_match = ngx.re.match

したがって、re_match シンボル名は ngx.re.match API 関数を指しています。 次の疑問は：どの正規表現がそれほど遅いのか？ということです。フレームグラフに示されているように、content_by_lua(nginx.conf:69):10 の Lua ソース行を直接参照することができます。しかし、Lua コードが汎用的で、複数の正規表現を保持する Lua テーブルを単にマッチングしているだけの場合、これだけでは問題となっている正規表現を特定するには不十分です。

最も遅い正規表現パターンのレイテンシ順ランキング

正規表現マッチングが最も CPU 時間を消費していることがわかったので、現在のライブプロセスでマッチングされた最も遅い正規表現を見つけるために、lj-slowest-ngx-re という別の標準アナライザを使用することができます。以下のように使用します：

$ orxray analyzer run lj-slowest-str-match-find -p 3584441 --y-var threshold_ns=1 --y-var max_hits=1000
Start tracing...
sub_regex_cache_count: 0
http: match
cache: ptr: 0x154bbc0, type: match, pat: "\w"
cache: ptr: 0x1517890, type: match, pat: "(?:.*)*css"
cache: ptr: 0x154a3a0, type: match, pat: ".*?js"
http: substitution
http: function substitution
...WARNING: reach samples count: 1000
=== start ===
max latency: 15844343 ns, ptr: 0x1517890
max latency: 13555 ns, ptr: 0x154a3a0
max latency: 8075 ns, ptr: 0x154bbc0
=== finish ===
Go to https://x5vrki.xray.openresty.com/targets/68/history/799249 for charts.

Web ブラウザでこの URL を開くと、以下の棒グラフが表示されます。

この棒グラフは、サンプリング時間枠内で実行された最も遅い正規表現の最大実行遅延を示しています。遅延はナノ秒単位で表示されています。明らかに、(?:.*)*css が絶対的に最も遅い正規表現であり、20.6 ミリ秒以上（または 20,671,282 ナノ秒）かかっています。また、他の正規表現と比べてもはるかに遅いことがわかります。経験豊富なユーザーであれば、貪欲な量指定子 .* と定数の接尾辞を組み合わせて使用すると、正規表現エンジンで積極的なバックトラッキングが発生する可能性があることをすぐに認識できるでしょう。この正規表現は、非貪欲版の量指定子を使用して最適化することができます：(?:.*?)css。

正規表現最適化後のパフォーマンス

最も遅い正規表現 (?:.*)*css を (?:.*?)css に最適化した後、最適化された正規表現でアプリケーションを再読み込みし、新しい C 言語レベルの CPU フレームグラフを再生成しました。

新しいフレームグラフの形状と特徴が以前のものとは大きく異なっていることがわかります。ボトルネックはもはや Lua コードを実行するコードパスではありません。代わりに、HTTP レスポンスデータを書き出す責任を持つ writev システムコールがボトルネックとなっています（上記のグラフで赤色でハイライトされている部分）。グラフ内の ngx_http_output_filter C 関数フレームに注目してください。この関数は、HTTP レスポンスヘッダーとボディデータを送信するために Nginx 出力フィルターチェーンを呼び出す責任があります。

最適化されたアプリケーションに対して lj-slowest-ngx-re ツールを再実行してみましょう。 結果のチャートは以下の通りです。

正規表現の最大レイテンシがはるかに短いことが分かります。わずか 58,660 ナノ秒、つまり約 59 マイクロ秒 です。

lua_regex_match_limit による PCRE バックトラッキングの制限

OpenResty の Lua Nginx モジュールは、単一の正規表現マッチングに対して実行される基本操作に厳格な制限を設けるための lua_regex_match_limit ディレクティブを提供しています。

例えば、以下の行を nginx.conf ファイルに追加することができます。

lua_regex_match_limit 100000;

そして、ngx.re.match API 関数呼び出しによって返されるエラーを必ずログに記録するようにしてください：

local m, err = re_match(content, regexes[i], "jo")
if err ~= nil then
    ngx.log(ngx.ERR, "re_math failed, re: ", regexes[i], ", error: ", err)
    return
end

マッチ制限を超えた場合、以下のようなエラーログメッセージが表示されます：

2022/07/13 21:05:13 [error] 3617128#3617128: *1 [lua] content_by_lua(nginx.conf:69):11: re_math failed, re: (.*)*css, error: pcre_exec() failed: -8, client: 127.0.0.1, server: localhost, request: "GET / HTTP/1.1", host: "127.0.0.1"

非バックトラッキングエンジン：RE2 と OpenResty Regex

PCRE は Perl 正規表現をほぼ完全にサポートしています。この柔軟性にはバックトラッキングに関連するコストが伴います。Google の RE2 や OpenResty Inc の商用 OpenResty Regex エンジンなど、バックトラッキングを行わない他の正規表現実装の検討もお勧めします。これらのエンジンは通常、オートマトン理論に基づくアルゴリズムを採用しています。残念ながら、RE2 はマッチングが遅くなる病的なケースはほとんどありませんが、その平均マッチング時間は、典型的な正規表現に対して PCRE よりも約 50% 遅くなります。一方、OpenResty Regex エンジンは PCRE と同等の平均性能（時にはさらに高速）を達成し、バックトラッキングの問題もありません。

正規表現の代替としての Lua 組み込みパターン

標準 Lua 5.1 言語は、標準 API 関数 string.match と string.find でサポートされている独自の正規表現言語構文を定義しています。 OpenResty XRay は、このようなパターンマッチング操作を分析するための動的トレーシングツールも提供しています。このトピックについては、別のチュートリアルで取り上げる予定です。

Docker・Kubernetes 内での正規表現パフォーマンスのトレース

OpenResty XRay ツールは、コンテナ化されたアプリケーションを透過的にトレースすることをサポートしています。 Docker と Kubernetes（K8s）コンテナの両方が透過的に動作します。対象のコンテナには、通常のアプリケーションプロセスと同様に、特別なアプリケーションや権限は必要ありません。OpenResty XRay Agent デーモンは、対象のコンテナの外部（ホストオペレーティングシステム上や特権を持つ独自のコンテナ内など）で実行する必要があります。

例を見てみましょう。まず、docker ps コマンドでコンテナ名またはコンテナ ID を確認します。

$ docker ps
CONTAINER ID   IMAGE                                       COMMAND                  CREATED         STATUS          PORTS     NAMES
4465297209d9   openresty/openresty:1.19.3.1-2-alpine-fat   "/usr/local/openrest…"   18 months ago   Up 45 minutes             angry_mclaren

ここでは、コンテナ名が angry_mclaren です。このコンテナ内でターゲットプロセスの PID を特定することができます。

$ docker top angry_mclaren
UID                 PID                 PPID                C                   STIME               TTY                 TIME                CMD
root                3605106             3605085             0                   19:40               ?                   00:00:00            nginx: master process /usr/local/openresty/bin/openresty -g daemon off;
nobody              3605692             3605106             0                   19:44               ?                   00:00:20            nginx: worker process

openresty ワーカープロセスの PID は 3605692 です。その後、通常通りこの PID に対して OpenResty XRay アナライザを実行します。

$ orxray analyzer run lj-slowest-ngx-re -p 3605692
Start tracing...
...
Go to https://x5vrki.xray.openresty.com/targets/68/history/684552 for charts.

OpenResty XRay は、長時間実行されているプロセスを特定のタイプ（「OpenResty」、「Python」など）の「アプリケーション」として自動的に検出することも可能です。

動的トレーシングツールの仕組み

すべてのツールは Y 言語で実装されています。OpenResty XRay は、Stap+³ または eBPF⁴ バックエンドのいずれかを使用してこれらを実行します。両者とも OpenResty XRay の一部であり、Linux カーネルの uprobes および kprobes 機能に基づく 100% 非侵入型の動的トレーシング技術を使用しています。

対象アプリケーションやプロセスからの協力は一切必要ありません。ログデータやメトリクスデータは使用せず、必要ともしません。実行中のプロセスのプロセス空間を厳密に読み取り専用で直接分析します。また、対象プロセスにバイトコードやその他の実行可能コードを一切注入しません。100% クリーンで安全です。

ツールのオーバーヘッド：非サンプリング時はゼロ

このチュートリアルで紹介した動的トレーシングツール lj-slowest-ngx-re は非常に効率的で、オンライン実行に適しています。

ツールが実行されておらず、アクティブにサンプリングしていない場合、システムおよび対象プロセスへのオーバーヘッドは厳密にゼロです。対象アプリケーションやプロセスに追加のコードやプラグインを一切注入しないため、固有のオーバーヘッドはありません。

サンプリング中、典型的なサーバーハードウェアにおいて、リクエストのレイテンシは平均で約 7 マイクロ秒（μs）しか増加しません。また、各 CPU コアで毎秒数万リクエストを処理する最速の OpenResty/Nginx サーバーにおいて、最大リクエストスループットの低下は検出限界以下のレベルです。

FAQ：Nginx 正規表現のパフォーマンス

Nginx の正規表現における破滅的なバックトラッキングとは？

ネストされた量指定子や貪欲な量指定子を含む PCRE パターンが、エンジンに膨大な数のマッチング経路を再試行させる現象です。本記事の事例では、(?:.*)*css がこれを引き起こし、1 回のマッチで最大 20.6 ミリ秒を記録して CPU コアを使い切りました。量指定子を非貪欲版（(?:.*?)css）に置き換えることで、レイテンシは 59 マイクロ秒まで短縮されました。

本番環境で遅い ngx.re.match 呼び出しを特定するには？

OpenResty XRay の lj-slowest-ngx-re アナライザを Nginx ワーカープロセスの PID に対して実行します。ngx.re.* 呼び出しで実行された正規表現パターンを、最大実行レイテンシ順にリアルタイムでランク付けします。ソースコードの変更や再起動は不要で、結果の棒グラフからボトルネックとなっているパターンが一目でわかります。

遅い正規表現は Nginx で ReDoS を引き起こしますか？

はい。病的なバックトラッキングを持つパターンは、Nginx ワーカープロセスを CPU 使用率 100% に追い込み、実質的なサービス拒否状態を引き起こす可能性があります。攻撃者は最悪ケースのマッチング時間を誘発する入力文字列を意図的に送り込むことがあります。lua_regex_match_limit ディレクティブで 1 回のマッチあたりの PCRE 操作数に上限を設け、信頼できない入力を扱う場合は RE2 や OpenResty Regex エンジンなどの非バックトラッキングエンジンの利用もご検討ください。

著者について

章亦春（Zhang Yichun）は、オープンソースの OpenResty^® プロジェクトの創始者であり、OpenResty Inc. の CEO および創業者です。

章亦春（GitHub ID: agentzh）は中国江蘇省生まれで、現在は米国ベイエリアに在住しております。彼は中国における初期のオープンソース技術と文化の提唱者およびリーダーの一人であり、Cloudflare、Yahoo!、Alibaba など、国際的に有名なハイテク企業に勤務した経験があります。「エッジコンピューティング」、「動的トレーシング」、「機械プログラミング」 の先駆者であり、22 年以上のプログラミング経験と 16 年以上のオープンソース経験を持っております。世界中で 4000 万以上のドメイン名を持つユーザーを抱えるオープンソースプロジェクトのリーダーとして、彼は OpenResty^® オープンソースプロジェクトをベースに、米国シリコンバレーの中心部にハイテク企業 OpenResty Inc. を設立いたしました。同社の主力製品である OpenResty XRay（動的トレーシング技術を利用した非侵入型の障害分析および排除ツール）と OpenResty Edge（マイクロサービスおよび分散トラフィックに最適化された多機能ゲートウェイソフトウェア）は、世界中の多くの上場企業および大企業から高い評価を得ております。OpenResty 以外にも、章亦春は Linux カーネル、Nginx、LuaJIT、GDB、SystemTap、LLVM、Perl など、複数のオープンソースプロジェクトに累計 100 万行以上のコードを寄与し、60 以上のオープンソースソフトウェアライブラリを執筆しております。

翻訳

英語版の原文と日本語訳版（本文）をご用意しております。読者の皆様による他の言語への翻訳版も歓迎いたします。全文翻訳で省略がなければ、採用を検討させていただきます。心より感謝申し上げます！