[AWS] ALB + Apache (prefork) で KeepAlive を使っていると低負荷でもヘルスチェックが落ちる事がある

最近関わっているプロジェクトで Apache + mod_php (prefork) の PHP アプリを ECS で運用しているのですが、CPU もメモリも余裕があるのに ALB のヘルスチェックに落ちてタスクが入れ替わる事がありました。Apache 自体触るのが久しぶりで今回の原因も初めて知ったので、同じ様に久々に触る方の参考になればと思い、検証環境で再現した結果と合わせてまとめます。

結論から書くと、ALB がターゲットとの接続を KeepAlive で使い回す為、その待ち状態の接続が Apache のワーカーを塞ぎ、毎回新しい接続を張るヘルスチェックだけが入れなくなる、と言うものでした。

ALB と KeepAlive の組み合わせでは「KeepAliveTimeout を ALB の idle timeout より長くしないと 502 になる」と言う話はよく見かけますが、こちらに言及した記事はあまり多くない様に見えます（最近は Apache で MPM=prefork を使う事があまりないからでしょう）。

環境

古い PHP フレームワークで作られた Web アプリです。

ALB → ECS (Fargate)
Apache HTTP Server 2.4 (prefork MPM) + mod_php
- MaxRequestWorkers 256
- KeepAlive On
- KeepAliveTimeout 180
ALB の idle timeout: 180 秒
ALB のヘルスチェック: 間隔 30 秒、タイムアウト 5 秒、unhealthy の閾値 2 回

KeepAliveTimeout を idle timeout 以上にしているのは AWS のドキュメントの推奨に従っている為です。

経緯

ある時からタスクがたまに unhealthy になって入れ替わる様になりました。CPU やメモリには余裕があり、アプリのログには何も出ていませんでしたが、Apache が次のようなエラーログを出力していました:

[mpm_prefork:error] [pid 7] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting

ワーカーを使い切っているっぽいのですが、そこまで大量にアクセスがあるわけではありませんでした。そこで mod_status の /server-status でワーカーの状態を見てみる事にしました。Debian の既定ではローカルからしか見られないので、コンテナの中から叩きます:

$ curl -s 'http://127.0.0.1/server-status?auto'
127.0.0.1
ServerVersion: Apache/2.4.x (Debian)
ServerMPM: prefork
（中略）
BusyWorkers: 9
IdleWorkers: 6
Scoreboard: KKKWKKKKW______.....（中略）.....

BusyWorkers は新しい接続を受け付けられないワーカーの数、IdleWorkers は受け付けられるワーカーの数です。Scoreboard はワーカー 1 つにつき 1 文字で状態を表していて、_ は接続待ち、W は処理中、K は KeepAlive 待ち、. はプロセスが起動していない空き枠です。

上の例だと Busy は 9 ですが、実際に処理しているのは W の 2 つ（うち 1 つはこの /server-status 自身）だけで、残りの 7 つは K です。

原因

prefork MPM では 1 つの接続を 1 つのプロセス（ワーカー）が受け持ちます。KeepAlive が有効だと、ワーカーはレスポンスを返した後も同じ接続で次のリクエストが来るのを KeepAliveTimeout の間待ち続けます。その間は何もしていなくても新しい接続は受け付けません。Scoreboard で言う K になります。

一方 ALB は、ターゲットとの接続を KeepAlive で使い回します。同時に流れたリクエストの数だけ接続が張られ、処理が終わっても残るので、Apache から見ると全部 K です。つまり、ある瞬間に ALB からターゲットへ重なったリクエストの数だけ、ワーカーが最大 KeepAliveTimeout 秒 (今回は 180 秒) 塞がります。

ところがヘルスチェックについては、30 秒間隔で来ているにもかかわらず K が残っていませんでした。毎回新しい接続を張って、終わったら閉じている様です。

従ってワーカーが全部 K で埋まると、

普通のリクエストは既存の接続（K のワーカー）に乗れるので通る
ヘルスチェックは新しい接続を張るので、空きがなくタイムアウトする

と言う状態になります。

もう1つ、KeepAlive には MaxKeepAliveRequests と言う設定があり、K がこの数のリクエストを処理するとワーカーは再び _ (Idle) に戻ります。ALB がリクエストをたくさん処理していれば、K にもリクエストがたくさん流れ、すぐ _ になりますが、暇な時間帯はなかなか到達せず遊んでいる K で溢れてしまいます。したがって一瞬多くのリクエストが来た後リクエストが収まってしまうと、今回の状況が起きやすいです（普通のワークロードだとあまりないかもしれません）。

検証環境で再現してみた

実際の ALB + Apache (prefork MPM) + mod_php の環境で試しました。ワーカーの上限より 1 本少ない 255 本と、ちょうどの 256 本のリクエストを一斉に送ってみます。PHP の処理がボトルネックでない事を保証する為、対象は数ミリ秒で返る何もしない単純なエンドポイントにしました:

N=255  # 上限ちょうどの場合は 256

# --parallel-immediate を付けると、接続の多重化を待たずに全部一斉に送れる。
curl -s --parallel --parallel-immediate --parallel-max $N \
  -o /dev/null -w '%{http_code}\n' \
  $(for i in $(seq $N); do echo "https://app.example.com/ping?n=$i"; done) | sort | uniq -c

255 本の場合

255 本全部が K になり（Busy 255 / Idle 0）、180 秒後に解放されました。空きが 1 つ残っているので、その間もヘルスチェックは通っています。

256 本の場合

経過時間	ヘルスチェック	別途 curl 1 本
送信前	healthy	200
+60 秒	unhealthy (Target.Timeout)	200 (0.3 秒)
+90 秒	unhealthy	000 (20 秒でタイムアウト)
+120 秒	新しいタスクに入れ替わり	200

ワーカーが埋まった後は /server-status 自体も応答しなくなります。

予想通りヘルスチェックは失敗し、タスクが入れ替わりました。別途打った curl は通ったり通らなかったりで、ALB のノード（AZ）ごとに接続のプールがあり、空き接続を持っていないノードに当たると新しい接続を張りにいって待たされるのだと思われます（挙動の詳細はドキュメントにも載ってないので推測）。

ここまでで分かる通り、効いてくるのは平均の負荷ではなく瞬間の同時接続数です。一瞬でもワーカー数ぶん重なれば、その後はアイドルなのに 180 秒ヘルスチェックが通らないので、CPU を見ても何も分かりません。実際、本番では同時に処理していたリクエストが最大 3 本のタスクで K が 15 本残っていました。

対策

MaxRequestWorkers を増やす

手っ取り早いですが、重なる数が上限を超えれば同じ事が起きるので根本的な解決にはなりません。mod_php は 1 プロセスあたりのメモリも大きいので、タスクのメモリとの兼ね合いもあります。

KeepAliveTimeout を短くする / KeepAlive を無効にする

K で塞がる時間が短くなります。ただし ALB の idle timeout より短くすると 502 の原因になるので、ALB 側も合わせて短くする必要があります。

KeepAlive 自体を無効にすれば K は発生しません。ALB とターゲットの間は VPC 内なので、平文なら毎回接続を張り直すコストは大抵気にならないと思います。ただし ALB とターゲットの間が HTTPS の場合は毎回 TLS ハンドシェイクが走る為、ターゲット側の CPU 負荷が無視できない場合があります。

event MPM + PHP-FPM に移行する

event MPM では KeepAlive 待ちの接続をリスナースレッドがまとめて面倒を見るので、ワーカーは塞がりません。nginx + PHP-FPM にしてもイベント駆動なので同様です。構成の変更は大きいですが、根本的にはこれが一番だと思います。

今回の対応

ひとまず /server-status の値を定期的に CloudWatch のカスタムメトリクスとして送り、ワーカーの状態を監視する様にしました。様子を見て、KeepAlive の無効化などを次に検討するかもしれません。

蛇足: AH00161 が出ても枯渇しているとは限らない

ここからは蛇足です。興味がある方だけどうぞ。

最初に手がかりにした AH00161 ですが、実は 255 本の時（ヘルスチェックは通っていた）に出て、256 本の時には出ていませんでした。Apache 2.4 の prefork のソースを見ると理由が分かります:

    else if (idle_count < ap_daemons_min_free) {
        /* terminate the free list */
        if (free_length == 0) {
            /* only report this condition once */
            if (!retained->maxclients_reported) {
                ap_log_error(APLOG_MARK, APLOG_ERR, 0, ap_server_conf, APLOGNO(00161)
                            "server reached MaxRequestWorkers setting, consider"
                            " raising the MaxRequestWorkers setting");
                retained->maxclients_reported = 1;
            }

AH00161 は「待機中のプロセスが MinSpareServers を下回り、新しく起動する枠もない」時に出るもので、リクエストが待たされたかどうかは関係ありません。しかもコメントの通り起動後 1 回しか出ないので、同じタスクで先に 255 本を試した時点で出し切っていた訳です。

なので AH00161 の有無で枯渇しているかどうかは判断できません。ワーカーの状態は mod_status で見るのが確実です。

まとめ

prefork では KeepAlive 待ちの接続（Scoreboard の K）もワーカーを 1 つ占有する
ALB はターゲットとの接続を使い回すので、同時に流れたリクエストの数だけ K が残る
ヘルスチェックは毎回新しい接続を張るので、K で埋まるとヘルスチェックだけが落ちる
効くのは平均の負荷ではなく瞬間の同時接続数なので、CPU などを見ても気付けない
AH00161 は枯渇の有無とは関係なく、しかも 1 回しか出ない

「CPU やメモリに余裕があるのに ALB のヘルスチェックが落ちる」と言う現象に遭遇したら、KeepAlive とワーカー数の関係を疑ってみてください。