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

nginx障害対応

アプリのせいではない失敗 — バッファ・ボディサイズ・コネクション再利用

TT Labで続きを見る

目標

ステータスコードが200なのにユーザーが遅いと言う障害を、nginxのバッファー・ボディサイズ・コネクションの設定から見つけ出せるようになります。そして、各設定が何を代償として払うのかを、数字で言えるようになります。

なぜ重要なのか

5xxは、ダッシュボードが教えてくれます。本当に長引くのは、誰も悪くないように見える障害です。開発チームは「うちは0.05秒で応答した」と言い、インフラチームは「サーバーは暇だ」と言うのに、ユーザーは7秒待っています。3つとも事実で、欠けているピースはnginxの中にあります。レスポンスがディスクにあふれたか、リクエスト本文が一時ファイルに落ちたか、リクエストごとに新しいTCPコネクションが開かれているかです。この3つは、すべてステータスコードに現れず、[warn]レベルのログ1行にだけ痕跡を残します。そのため、error_logをwarnで開けておくことが、この障害を見る唯一の方法です。

ステップ

  1. /root/ngb/upstream.pyを保存して起動し、/root/ngb/nginx.confを作成してnginxを起動します。ポート8088でlistenし、/app/をupstream appグループ(ポート9101)にプロキシします。error_logは/root/ngb/logs/error.logにwarnレベル、アクセスログは/root/ngb/logs/access.logに出力し、フォーマットに$upstream_response_time、$request_time、$upstream_statusをすべて入れます。client_max_body_sizeはまだ入れません。確認: http://127.0.0.1:8088/app/が200である必要があります(ブラウザーのプレビューで開いて確認できます)。
  2. 2種類の遅いリクエストを、それぞれ1回ずつ送ります。
    • アップストリームが遅い場合: http://127.0.0.1:8088/app/slow?d=4
    • 転送が遅い場合: http://127.0.0.1:8088/app/big?n=8000000をcurl --limit-rate 1000kで呼び出します 2つのリクエストのアクセスログの行を/root/ngb/attribute.logに抜き出しておき、/root/ngb/attribute.csvを作成します。1行目はcase,upstream_time,request_time,verdictで、2行が続きます。caseはslow-upstreamとslow-transfer、verdictはupstreamまたはtransferです。
  3. ステップ2の大きなレスポンスがerror.logに残した警告を見つけて、/root/ngb/case-spill.txtを作成します。4行で、プレースホルダーは、順に角括弧の中のレベル、ログに書かれた一時ファイルのパスそのまま、同じリクエストのアクセスログのステータスコード、disk-spillとupstream-heldのどちらかです。
    level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
status=<같은 요청의 액세스 로그 상태 코드>
tradeoff=<disk-spill 또는 upstream-held>
  4. /nobuf/パスを追加します。同じupstream appにプロキシしますが、そのブロックの中にproxy_buffering off;を入れます。reloadしてから、http://127.0.0.1:8088/nobuf/big?n=8000000を同じ--limit-rate 1000kで受け取り、/root/ngb/case-nobuf.txtを作成します。4行で、プレースホルダーは、順にusの欄ではなくutの欄の値そのまま、rtの欄の値そのまま、noneとspilledのどちらか、disk-spillとupstream-heldのどちらかです。
    upstream_time=<us 칸이 아니라 ut 칸 값 그대로>
request_time=<rt 칸 값 그대로>
warn=<none 또는 spilled>
tradeoff=<disk-spill 또는 upstream-held>
  5. 3MBの本文をhttp://127.0.0.1:8088/app/toobigにPOSTします。ステータスコード、アクセスログのusの欄、そして/root/ngb/upstream.logにそのリクエストが何件残ったかを確認して、/root/ngb/case-413.txtを作成します。4行で、プレースホルダーは、順にステータスコード、アクセスログのusの欄の値、アップストリームのログに残った件数、この失敗を解決するディレクティブ名です。
    status=<상태 코드>
upstream_status=<액세스 로그 us 칸 값>
app_saw=<업스트림 로그에 남은 건수>
fix=<이 실패를 푸는 지시자 이름>
    そのあと、そのディレクティブを10mに設定してreloadし、http://127.0.0.1:8088/app/uploadに同じ3MBをPOSTして、200が返るようにします。
  6. 500KBの本文をhttp://127.0.0.1:8088/app/spillにPOSTすると、error.logに一時ファイルの警告がもう1つ出ます。/root/ngb/case-bodyspill.txtを作成します。3行で、プレースホルダーは、順に角括弧の中のレベル、ログに書かれた一時ファイルのパスそのまま、本文をメモリに保持するサイズを決めるディレクティブ名です。
    level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
fix=<본문을 메모리에 담는 크기를 정하는 지시자 이름>
    そのあと、そのディレクティブを1mに設定してreloadし、http://127.0.0.1:8088/app/nospillに同じ500KBをPOSTして、今度は警告が出ないことを確認します。
  7. コネクション再利用を実測します。まず現在の状態でhttp://127.0.0.1:8088/app/を10回呼び出し、upstream.logのconn番号が何種類あるかを数えます。次に、upstream appブロックにkeepalive 16;を、/app/ブロックにproxy_http_version 1.1;とproxy_set_header Connection "";を入れてreloadし、もう一度10回呼び出して、同じ方法で数えます。/root/ngb/keepalive.txtを作成します(プレースホルダーは、順に設定前のコネクション数と設定後のコネクション数です)。
    before=<설정 전 커넥션 수>
after=<설정 뒤 커넥션 수>
  8. /root/ngb/runbook.mdを作成します。## 증상별 첫 확인、## 버퍼링、## 본문 크기、## 커넥션 재사용という4つのh2見出し(韓国語の見出しは、順に「症状別の最初の確認」「バッファリング」「ボディサイズ」「コネクション再利用」を意味します)が必要で、proxy_buffering、client_max_body_size、client_body_buffer_size、keepalive、upstream_response_timeの5つの単語がすべて登場している必要があり、ステップ2で測った2つの時間の値が、数字で引用されている必要があります。

参考

測定できるプロキシを立てる

/root/ngb/upstream.pyを保存して起動し、/root/ngb/nginx.confを作成してnginxを起動します。ポート8088でlistenし、/app/をupstream appグループ(ポート9101)にプロキシします。error_logは/root/ngb/logs/error.logにwarnレベル、アクセスログは/root/ngb/logs/access.logに出力し、フォーマットに$upstream_response_time、$request_time、$upstream_statusをすべて入れます。client_max_body_sizeはまだ入れません。確認: http://127.0.0.1:8088/app/が200である必要があります(ブラウザーのプレビューで開いて確認できます)。

前のラボと同じ障害発生器を、/root/ngbの下に再度起動します。このラボの勝負は、アクセスログのフォーマットで決まります。アップストリームが使った時間と全体の時間を一緒に残さないと、ステップ2から何も見えません。アップストリームはupstreamブロックにまとめておいてください。ステップ7で、そのブロックの中にディレクティブを1つ入れることになります。

アプリが遅いのか、転送が遅いのか

2種類の遅いリクエストを、それぞれ1回ずつ送ります。

2種類の遅さを、それぞれ1回ずつ作ります。アップストリームが4秒かかるリクエストと、レスポンスは一瞬で出るのにクライアントがゆっくり受け取るリクエストです。curlの--limit-rateで、遅いクライアントを再現できます。2つのリクエストのアクセスログの行を別々に抜き出しておき、utとrtを比較してください。

ディスクにあふれるレスポンス

ステップ2の大きなレスポンスがerror.logに残した警告を見つけて、/root/ngb/case-spill.txtを作成します。4行で、プレースホルダーは、順に角括弧の中のレベル、ログに書かれた一時ファイルのパスそのまま、同じリクエストのアクセスログのステータスコード、disk-spillとupstream-heldのどちらかです。

level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
status=<같은 요청의 액세스 로그 상태 코드>
tradeoff=<disk-spill 또는 upstream-held>

ステップ2の大きなレスポンスが、error.logに何を残したかを見てください。レベルがerrorではないという点と、同じリクエストのアクセスログのステータスコードが何かが、このステップの要点です。この障害は、ステータスコードでは絶対に見えません。

バッファリングを無効にすると何が変わるのか

/nobuf/パスを追加します。同じupstream appにプロキシしますが、そのブロックの中にproxy_buffering off;を入れます。reloadしてから、http://127.0.0.1:8088/nobuf/big?n=8000000を同じ--limit-rate 1000kで受け取り、/root/ngb/case-nobuf.txtを作成します。4行で、プレースホルダーは、順にusの欄ではなくutの欄の値そのまま、rtの欄の値そのまま、noneとspilledのどちらか、disk-spillとupstream-heldのどちらかです。

upstream_time=<us 칸이 아니라 ut 칸 값 그대로>
request_time=<rt 칸 값 그대로>
warn=<none 또는 spilled>
tradeoff=<disk-spill 또는 upstream-held>

同じ8MBのレスポンスを、バッファリングを無効にした経路でもう一度受け取ってみてください。一時ファイルの警告が消える代わりに、アクセスログの2つの数字の関係が逆転します。その逆転が何を意味するかが、このステップの答えです。

アプリケーションが永遠に見られない413

3MBの本文をhttp://127.0.0.1:8088/app/toobigにPOSTします。ステータスコード、アクセスログのusの欄、そして/root/ngb/upstream.logにそのリクエストが何件残ったかを確認して、/root/ngb/case-413.txtを作成します。4行で、プレースホルダーは、順にステータスコード、アクセスログのusの欄の値、アップストリームのログに残った件数、この失敗を解決するディレクティブ名です。

status=<상태 코드>
upstream_status=<액세스 로그 us 칸 값>
app_saw=<업스트림 로그에 남은 건수>
fix=<이 실패를 푸는 지시자 이름>

そのあと、そのディレクティブを10mに設定してreloadし、http://127.0.0.1:8088/app/uploadに同じ3MBをPOSTして、200が返るようにします。

3MBの本文をアップロードしてみてください。ステータスコードより重要なのは、そのリクエストがアップストリームに行ったかどうかです。アクセスログのアップストリームのステータスコードの欄と、アップストリームサーバー自身のログの、2か所で確認できます。確認が終わってから、設定を直して通してください。

リクエスト本文もディスクにあふれる

500KBの本文をhttp://127.0.0.1:8088/app/spillにPOSTすると、error.logに一時ファイルの警告がもう1つ出ます。/root/ngb/case-bodyspill.txtを作成します。3行で、プレースホルダーは、順に角括弧の中のレベル、ログに書かれた一時ファイルのパスそのまま、本文をメモリに保持するサイズを決めるディレクティブ名です。

level=<대괄호 안 수준>
path=<로그에 적힌 임시 파일 경로 그대로>
fix=<본문을 메모리에 담는 크기를 정하는 지시자 이름>

そのあと、そのディレクティブを1mに設定してreloadし、http://127.0.0.1:8088/app/nospillに同じ500KBをPOSTして、今度は警告が出ないことを確認します。

413のしきい値よりは小さいが、メモリバッファーよりは大きい本文をアップロードすると、警告がもう1つ出ます。レスポンス側の一時ファイルとは別のディレクトリに落ちるので、パスをよく見てください。直したあとは、別のパスでもう一度アップロードして、警告が出ないことを確認します。

3行すべてがそろって初めて、コネクションが再利用される

コネクション再利用を実測します。まず現在の状態でhttp://127.0.0.1:8088/app/を10回呼び出し、upstream.logのconn番号が何種類あるかを数えます。次に、upstream appブロックにkeepalive 16;を、/app/ブロックにproxy_http_version 1.1;とproxy_set_header Connection "";を入れてreloadし、もう一度10回呼び出して、同じ方法で数えます。/root/ngb/keepalive.txtを作成します(プレースホルダーは、順に設定前のコネクション数と設定後のコネクション数です)。

before=<설정 전 커넥션 수>
after=<설정 뒤 커넥션 수>

まず現在の状態で10回送り、アップストリームが見たコネクションがいくつあるかを数えてください。次に3つすべてを入れてもう一度数えると、数字が大きく変わります。1つ欠けても何の効果もないので、変わらなければ、3つのうち何が欠けているかを見てください。

運用判断の基準書

/root/ngb/runbook.mdを作成します。## 증상별 첫 확인、## 버퍼링、## 본문 크기、## 커넥션 재사용という4つのh2見出し(韓国語の見出しは、順に「症状別の最初の確認」「バッファリング」「ボディサイズ」「コネクション再利用」を意味します)が必要で、proxy_buffering、client_max_body_size、client_body_buffer_size、keepalive、upstream_response_timeの5つの単語がすべて登場している必要があり、ステップ2で測った2つの時間の値が、数字で引用されている必要があります。

各設定の長所だけを書いても、ドキュメントとは言えません。何を得て何を差し出すのかを、前のステップで測った数字で書いておけば、6か月後に誰かがその値に触れられるようになります。