TT Lab
はじめる
学ぶ 学習パス コース

nginx障害対応

アプリは0.049秒で終えたのに、ユーザは7秒待った

TT Labで続きを見る

一言でいうと

アプリは0.049秒で処理を終えたのに、ユーザーは7秒待ちました。ステータスコードは200で、アプリケーションログにも異常はありません。この種の障害は、nginxのバッファーとコネクションの設定にだけ痕跡を残します。

なぜ必要なのか

5xxは、それでも目立ちます。ダッシュボードが赤くなり、アラートが鳴ります。本当に長引くのは、誰も悪くないように見える障害です。

ユーザーは「レポート画面が遅い」と言います。開発チームはアプリのログを調べて、「うちは0.05秒で応答しました」と答えます。インフラチームはCPU・メモリ・ネットワークのグラフを表示して、「サーバーは暇です」と答えます。どちらも事実です。そしてユーザーも事実を言っています。この会議は結論が出ないまま終わり、翌週まったく同じ形でまた開かれます。

欠けているピースは、nginxの中にあります。レスポンスがディスクにあふれたか、リクエスト本文が一時ファイルに落ちたか、リクエストごとに新しいTCPコネクションが作られているかです。この3つは、すべてステータスコードに現れません。

バッファリング: レスポンスがディスクにあふれる瞬間

proxy_bufferingのデフォルトはonで、その理由は妥当です。nginxがアップストリームのレスポンスをできるだけ早く受け取りきってアップストリームのコネクションを解放し、そのあと遅いクライアントにはnginxがゆっくり流します。アップストリームのスレッドが、遅いユーザーに引き止められません。

問題は、レスポンスがバッファー(proxy_buffer_size + proxy_buffers)より大きいときです。そのときnginxは、余った部分をディスクの一時ファイルに書きます。実測した行です。

[warn] an upstream response is buffered to a temporary file
  /var/lib/nginx/proxy/1/00/0000000001 while reading upstream,
  request: "GET /app/big?n=8000000 HTTP/1.1"

ここで2つのことに注目する必要があります。

1つ目は、レベルが[error]ではなく[warn]であることです。ほとんどのチームはerror_logをerrorレベルにしているか、アラートを[error]という文字列にだけ設定しています。それではこの行は、永遠に誰にも届きません。warnレベルで開けておくことが、この障害を見る唯一の方法です。

2つ目は、同じリクエストのアクセスログは200であることです。ステータスコードでは絶対に見えません。

同じ8MBのレスポンスを、バッファリングを有効にした経路と無効にした経路でそれぞれ受け取って測った数字です。

proxy_buffering on   →  ut=0.049  rt=4.173   + [warn] 임시 파일
proxy_buffering off  →  ut=3.188  rt=3.189   경고 없음

この表がバッファリングの正体をそのまま示しています。有効にすると、アップストリームは0.049秒だけ引き止められ、残りはnginxが引き受けます。そのかわり、ディスクにあふれます。無効にすると、ディスクにあふれない代わりに、アップストリームがクライアントの受信完了まで引き止められます。utがrtに張り付くのが、その証拠です。

そのため、判断は次のように分かれます。

ただし、正直に書いておきます。このラボ環境で、1秒間隔でチャンクを流すストリーミングを測定したところ、proxy_bufferingを有効にした側も無効にした側も、チャンクは1秒間隔で届きました。nginxは、クライアントが受け取れる限り、読み取ったそばから流します。「バッファリングを有効にするとストリーミングが途切れる」というよくある説明は、少なくともこの条件では再現されませんでした。ストリーミングでバッファリングを無効にする本当の理由は、レスポンスが大きくなったときにディスクにあふれないようにすることと、アップストリームの占有を意図的に維持することに近いです。

ボディサイズ: アプリが永遠に見られない413

client_max_body_sizeのデフォルト値は1mです。これを超えるアップロードは、nginxが直接413で切ります。

[error] client intended to send too large body: 3000000 bytes,
  request: "POST /app/toobig HTTP/1.1"

同じリクエストのアクセスログです。

413 ut=- rt=0.002 us=- "POST /app/toobig HTTP/1.1"

utとusが、どちらもダッシュです。アップストリームに行ったことがありません。ラボでアップストリームサーバーのログを数えてみると、本当に0件です。開発チームが「うちのログにそのリクエストはありません」と言うとき、それは言い逃れではなく、正確な事実です。

ボディサイズには、もう1つ設定が付いており、こちらはあまり知られていません。client_body_buffer_size(デフォルトは16k、プラットフォームによって8k)を超える本文は、メモリではなくディスクに行きます。

[warn] a client request body is buffered to a temporary file
  /var/lib/nginx/body/0000000003, request: "POST /app/spill HTTP/1.1"

500KBのフォームアップロードが毎秒数百件入ってくるシステムなら、この行が毎秒数百回出力され、その分だけディスクに書いて消します。ステータスコードはすべて200です。

コネクション再利用: 3行すべてが必要

アップストリームのKeep-Aliveは、3つが同時にそろって初めて動作します。1つ欠けても、静かにオフになります。

upstream app {
  server 127.0.0.1:9101;
  keepalive 16;                      # ①
}
location /app/ {
  proxy_http_version 1.1;            # ②
  proxy_set_header Connection "";    # ③
  proxy_pass http://app/;
}

同じリクエスト10件を送って、アップストリームが見たTCPコネクション数を実測しました。

設定 アップストリームが見たコネクション
何もなし 10
①のみ 10
① + ② 10
① + ② + ③ 1

②だけを入れて終わりにするケースが特に多いです。HTTP/1.1に上げたから大丈夫だろうと考えがちですが、クライアントが送ったConnectionヘッダーがそのままアップストリームに渡されて、毎回コネクションが切れます。③がそのヘッダーを消します。

再利用できないと、リクエストごとに新しいソケットが開いて閉じられ、TIME_WAITが溜まります。普段は何の症状もなく、トラフィックがしきい値を超えた瞬間に、ポートの枯渇で一気に破綻します。そしてそのとき見える症状はconnect() failed、つまり502です。原因はコネクションの設定なのに、症状は「バックエンドが死んだ」ように見えます。症状と原因が別の場所にあるというこのコースのテーマが、ここでも繰り返されます。

現場での姿

error_logのレベルをwarnにして開けておきます。この節で扱った2つの一時ファイルの警告は、どちらも[warn]です。errorに絞ってしまうと、これらの障害は存在しないことになります。ログ量が心配なら、レベルを絞るのではなく、ローテーション周期を短くします。

ログフォーマットに$upstream_response_timeと$request_timeを一緒に残します。この2つの欄がないと、「アプリが遅いのか、転送が遅いのか」という最初の分岐を分けられず、その分岐を分けられなければ、会議が繰り返されます。

設定を変える前に測ります。バッファーを大きくするのも、バッファリングを無効にするのも、タダではありません。何を得て、何を差し出すのかを数字で書いておかないと、6か月後には誰もその値に触れなくなります。

次のラボですること

同じ8MBのレスポンスを、バッファリングを有効にした経路と無効にした経路で受け取って2つの数字を比較し、413がアプリケーションに到達すらしないことをアップストリームのログで証明し、コネクション再利用を3点セットの前後で実測します。最後に、それらの数字を盛り込んだ運用判断の基準書を書きます。