curlは区間を分けて教えてくれる

一言でいうと

curl -wのタイミング変数を使うと、1回のリクエストで、名前解決 / 接続 / TLS / サーバー処理のどこが遅いのかを切り分けられます。この1行が、「ネットワークのせいか、アプリケーションのせいか」という論争を終わらせます。

なぜ必要なのか

デプロイ直後に、応答が遅くなりました。インフラチームはアプリケーションの問題だと言い、開発チームはネットワークの問題だと言います。双方とも、自分のダッシュボードでは正常に見えます。

この状況で必要なのは、より多くのダッシュボードではなく、1つのリクエストの時間を区間ごとに分解して見ることです。

curl -sS -o /dev/null -w 'dns:%{time_namelookup} conn:%{time_connect} tls:%{time_appconnect} ttfb:%{time_starttransfer} total:%{time_total}\n' https://api.example.com/health

各値はリクエスト開始からの累積時間なので、差を見れば各区間の所要時間が出ます。解釈のルールは明確です。

どこが大きいか	結論
time_namelookup	名前解決の問題。DNSの区間へ
time_connect - time_namelookup	TCP接続。経路やファイアウォール
time_appconnect - time_connect	TLSハンドシェイク。証明書チェーン、プロトコルのネゴシエーション
time_starttransfer - time_appconnect	サーバーが最初のバイトを作る時間。アプリケーション
time_total - time_starttransfer	本文の転送。サイズや帯域

time_connectまでは正常なのに、time_starttransferだけが大きければ、ネットワークは無実です。その場で論争が終わります。

どう動くのか

ステータスコードだけを取り出す。curl -s -o /dev/null -w '%{http_code}' URLは、本文を捨てて、ステータスコードだけを出力します。ヘルスチェックスクリプトの基本形です。接続そのものが失敗すると、000が出ます。この値を別に処理して初めて、「サーバーが5xxを返した」と「サーバーに届かなかった」を区別できます。

ヘッダーだけを受け取る。curl -sI URLは、HEADリクエストを送って、ヘッダーだけを受け取ります。Content-Lengthが期待と違えば、キャッシュやプロキシが挟まっている可能性があります。

リダイレクト。curlは、デフォルトではリダイレクトをたどりません。-Lを付けて初めて、たどります。そのため、同じURLに対して、-Lなしでは301、付ければ200が出るのが正常です。ヘルスチェックでこれを知らないと、「なぜ301が出るのか」で時間を使います。

タイムアウトは選択ではありません。--max-timeなしでヘルスチェックを動かすと、相手が応答しないときに、そのスクリプトが永遠に止まります。cronが5分ごとにこのようなスクリプトを起動すると、プロセスが溜まります。ヘルスチェックには、必ず最大待ち時間をかけます。

現場での姿

ローカルで再現する。ネットワークが遮断された環境でも、python3 -m http.server1つで、HTTPの動作の大半を再現できます。ステータスコード、ヘッダー、リダイレクト、未実装メソッドの応答まで、実際のとおりです。ラボがこの方式を使う理由でもあり、実務でも、クライアントコードを検証するときによく使います。

JSONの応答は、jqで切り出します。curl -s URL | jq -r '.items | length'のようにパイプでつなぐと、スクリプトで値をすぐに取り出せます。ただし、curlが失敗したときに、jqが空の入力を受け取って静かに通過してしまう罠があるので、スクリプトではset -o pipefailが必要です。

ヘルスチェックスクリプトの契約。良いヘルスチェックは、3つを区別して知らせます。正常(2xx)、応答は来たが異常(4xx/5xx)、そもそも届かない(接続失敗)の3つです。3つを1つの失敗にまとめると、アラートを受け取っても、どこから見ればよいかわかりません。

遅い区間を数字で指し示す

「APIが遅い」という報告は、どこを見ればよいかを教えてくれません。curlの時間の書式変数は、リクエスト1つを5つの区間に分解してくれます。どの区間が膨らんだかが、そのまま、どのチームの問題かです。

curl -sS -o /dev/null -w \
  'dns=%{time_namelookup} tcp=%{time_connect} tls=%{time_appconnect} \
ttfb=%{time_starttransfer} total=%{time_total}\n' \
  https://example.com/api/health

数字は累積です。time_connectが0.32なら、接続までに0.32秒かかったという意味であり、接続に0.32秒かかったという意味ではありません。各段階で実際に使った時間は、引き算して求めます。

区間	計算	膨らんだときに疑うもの
名前照会	namelookup	resolv.confのsearchドメイン、DNSサーバーの応答
TCP接続	connect - namelookup	ネットワークの往復時間、ファイアウォール、acceptキュー
TLSハンドシェイク	appconnect - connect	証明書チェーンの長さ、OCSP照会、セッション再利用の失敗
サーバー処理	starttransfer - appconnect	アプリケーションとDB
本文の転送	total - starttransfer	応答サイズ、帯域、圧縮の有無

TTFBだけが大きければ、そこからはアプリケーションの担当です。前の3つの区間がすべて小さく、starttransferだけが大きければ、ネットワークは潔白です。逆に、connectが大きいのにstarttransferが小さければ、コードをいくら覗いても答えが出ません。

1回だけ測って判断しません。TLSセッションの再利用、DNSキャッシュ、コネクションプールのために、最初のリクエストと2回目のリクエストは、性質がまったく違います。最低10回は実行して、中央値とテール値を一緒に見ます。

for i in $(seq 20); do
  curl -sS -o /dev/null -w '%{time_starttransfer}\n' https://example.com/api/health
done | sort -n | awk '{a[NR]=$1} END {print "중앙값", a[int(NR/2)], "p95", a[int(NR*0.95)]}'

平均ではなく、テールを見ます。平均応答時間は良いのに、ユーザーが遅いと言う状況はよくあります。ユーザーは、自分が経験した最も遅いリクエストを覚えているからです。

次のラボですること

ローカルにHTTPサーバーを起動して、ステータスコード・ヘッダー・タイミング・JSONをそれぞれ取り出してみます。リダイレクトをたどるときとたどらないときの違い、未実装メソッドの応答を自分で確認し、最後に、3つの状況を区別して報告するヘルスチェックスクリプトを作ります。