Docker上のApacheの設定による障害の原因究明・対策までの記録

あらすじ

事は数週間前。週明けから開発陣から、開発環境のサーバーからのレスポンスがタイムアウトする事態が発生していた。
調査していくと事態は開発環境ではなく、サービスが稼働する本番環境でも同様の問題が発生していることが発覚。
表面化するほど重大な事態ではなかったものの、重大な障害につながる可能性を考慮し、開発チームは原因の究明と対策にあたるのだった。

環境の概要

• php 7.1.12
• Laravel Lumen 5.5系
• Mysql 5.6
• Apache 2.4
• AWS ECS

事態の発覚

問題が起こったのはLaravelの亜種であるLumenにより作られた、とあるアプリのAPIサーバーである。
アプリ開発チームよりいくつかの処理において504エラーが発生しているとの報告を受けた。ちょうどその時は新しい機能を追加したあとだったので、バグが潜んでいるのだろうと思いECSがCloudWatch Logs上に流しているログを調査した。

しかし、ログには何もなかった。プロセスはログを出力する前に落ちてしまい、タイムアウトによりエラーとなっていたのだ。
さらに我々を苦しめたのは、直前に追加した機能とは関係のないエンドポイントへのアクセスでも、同様のタイムアウトが発生していたことだ。コードの問題ではない可能性がある。

ECSのログには問題のリクエストが来た時のログが流れないため、他に何か怪しいログはないかと、問題が発生した時刻周辺のログを漁った。それはもう検索などではなく、人力だった。
すると明らかに問題のあるログを発見することができた。

[Mon Dec 10 00:41:44.624052 2018] [mpm_prefork:error] [pid 14] (12)Out of memory: AH00159: fork: Unable to fork new process

メモリ不足だった。

問題は表面化していないものの、実際にサービスが稼働する本番環境にも同様のログを発見しため、我々サーバーサイドチームはこの問題の解決を優先して動くこととした。

原因究明

原因を追求するに当たって、問題の発生時期とその直前の変更について調査した。
メモリ不足のエラーは、ある時点から頻発していることがわかった。しかし、それは直前のリリースからおよそ2週間ほどたってから発生していたため、直接的な関係があるか怪しかった。

次にECSのリソースに関する状態を調査した。すると危うい事実が発覚する。
ECSの MemoryUtilization　がリリースから1週間後くらいから徐々に増加して、メモリ不足の問題が発生する頃には使用率が80％を超え、コンテナのダウンと再起動が繰り返されていた。

まずはコードを疑う

我が社にはインフラの専門チームが存在するので、私はそこに協力を仰ぎ、コンテナの再起動と意見を伺った。
コンテナを再起動することで何とか事態は収まったが根本的解決ではない。
インフラチームの見解としては、まずコードを疑いメモリが逼迫するようなコードを書いてないかを確認すべきとのことだった。私も同意見だった。

我々はまず、処理の負荷を計測するためのログ出力を行うようにした。
下記はそのログである。

{
  "message": "ApiLog",
  "context": {
    "method": "GET",
    "path": "posts",
    "request": {
      "offset": "0",
      "limit": "10"
    },
    "memory_get_usage_m": 2,
　　　　　　　　"memory_get_usage_sys_m": 3,
    "execution_time_msec": 0.7986888885498047
  },
  "level": 200,
  "level_name": "INFO",
  "channel": "*****",
  "datetime": {
    "date": "2018-12-13 18:50:25.665076",
    "timezone_type": 3,
    "timezone": "Asia/Tokyo"
  },
  "extra": {
    "url": "/posts?offset=0&limit=10",
    "ip": "127.0.0.1",
    "http_method": "GET",
    "server": "localhost",
    "referrer": null,
    "file": "/project/app/Http/Middleware/ApiLog.php",
    "line": 79,
    "class": "App\\Http\\Middleware\\ApiLog",
    "function": "terminate"
  }
}

Laravelのミドルウェアにてログ出力を行う処理を追加した。
これにより全てのエンドポイントへのリクエストごとに、メモリの使用量・所要時間を計測できるようにした。
早速私は直前のリリースにより追加したコードをコメントアウトし、これらを計測した。

しかし、メモリ使用量は10kBも減っておらず、処理速度も同様に無視できるレベルの変化だった。
原因はコードでもなかった。

Apacheの設定を疑う

コードに問題がないとすれば他の可能性を考える。
時間経過によりメモリの使用量が増えていくという現象を再現するため、ローカルのDockerが使用しているメモリを監視しながら、リクエストを飛ばしていくことにした。

DockerコンテナのCPU/Memoryの使用状況を見るためには下記のコマンドを入力する。

Docker stats コンテナ名

この状態を監視しながらリクエストを飛ばす。すると見事にMEM USAGEが増加していった。
プロセスの状況を確認すると、大量のhttpd子プロセスが立ち上がっていた。
プロセスの設定に関して調べていくと、どうやらMaxConnectionPerChildという設定があるらしい。

現状の設定を確認したところ、何とその設定は0、無制限にプロセスが立ち上がる設定だった。
これが原因だった。

対策方法

Apacheのprefork動作時の設定を、このサイトの情報を元に次のように変更した。

<IfModule mpm_prefork_module>
    StartServers                2
    MinSpareServers             2
    MaxSpareServers             2
    ServerLimit                30
    MaxRequestWorkers          30
    MaxConnectionsPerChild   1000
</IfModule>

これらの数字はインスタンスの性能などから算出されたものなので、実際に設定する時は参考サイト参考にして、各々の環境に合わせ設定する必要がある。

この設定をして簡単な負荷テストを行なったところ、メモリの使用率は安定し、メモリ不足のログも出なくなった。

一旦事態は収束しそうだが、リクエストをさばけないなどの事態に備え、今後の状況を監視するためにCloudWatch Insightを用いて状況を可視化できるようにした。クエリは下記のようなもの。

filter message = "ApiLog"
| stats
min(context.memory_get_usage_m) as MinMemoryUsageMB,
avg(context.memory_get_usage_m) as AvgMemoryUsageMB,
max(context.memory_get_usage_m) as MaxMemoryUsageMB by bin(5min) as DateTime

filter message = "ApiLog"
| stats
min(context.execution_time_msec) as MinExecutionTimeMS,
avg(context.execution_time_msec) as AvgExecutionTimeMS,
max(context.execution_time_msec) as MaxExecutionTimeMS by bin(5min) as DateTime

これにより設定適用後と前の状況を計測できるようにした。

おわりに

何故このリリース1週間後から負荷が高くなったのかは明確にわかっていない。
サービスの利用者は順調に増えていたことから、アクセス数の増加と機能追加による負荷の微増という二つの要素が重なって、負荷が高くなっていったのではないかと推測している。

ECSを使用したサービスを作っていて同様の問題を抱えた開発者は、コンテナイメージ内の設定を確認すると良いだろう。
とくに拾ってきたイメージを使う時は要注意。最初は問題なくても、利用者が増えて顕在化する問題がある。