curlの-wオプションでリクエストの各フェーズの所要時間を分解する

  • curl
  • HTTP
  • CLI

この記事は、構成と文章の整理にAIを使っています。
あくまで読みやすくするための補助で、内容そのものをAIにすべて任せて書いているわけではありませんが、ところどころ相談しながら整えています。

APIのレスポンスが遅い時、どのフェーズで時間がかかっているか切り分けたくなる。DNS解決なのか、TCP接続なのか、サーバー側の処理なのか、レスポンスの転送なのか。curlの-wオプションを使えばcurlコマンド単体でこれが分解できる。

使うオプション

-w（--write-out）に変数を埋め込んだフォーマット文字列を渡すと、リクエスト完了後にその内容が出力される。

ターミナル
curl "https://api.example.jp/controller/action" -o /dev/null -s -w \
"resolv name complete @%{time_namelookup} sec\n\
target server connection complete @%{time_connect} sec\n\
TLS handshake complete @%{time_appconnect} sec\n\
target server http request send complete @%{time_pretransfer} sec\n\
http content output start @%{time_starttransfer} sec\n\
http content receive complete. total time %{time_total} sec\n"
  • -o /dev/null: レスポンスボディは見ないので捨てる
  • -s: プログレスメーターを消す（2>/dev/nullでエラー出力ごと捨てるより意図が明確）

各変数の意味

sequenceDiagram
    participant Client
    participant DNS
    participant Server

    Client->>DNS: 名前解決
    DNS-->>Client: time_namelookup
    Client->>Server: TCP接続
    Server-->>Client: time_connect
    Client->>Server: TLSハンドシェイク
    Server-->>Client: time_appconnect
    Client->>Server: リクエスト送信
    Server-->>Client: time_pretransfer
    Server-->>Client: レスポンス転送開始 (time_starttransfer)
    Server-->>Client: レスポンス転送完了 (time_total)

httpsの場合、time_connectはTCP接続完了時点、time_appconnectはTLSハンドシェイク完了時点で、この2つは別フェーズになる。ここを分けずにtime_connectだけ見ると、TCP接続自体は速いのにTLSに時間がかかっているケースを見逃す。

time_pretransferは名前の通り「転送直前まで」の時間で、厳密にはリクエスト送信完了そのものではないが、実用上はリクエスト送信完了とほぼ同じタイミングとして扱って問題ない。

time_starttransferはレスポンスの最初の1バイトを受け取るまでの時間なので、サーバー側の処理時間のうち大部分はここまでに含まれる。time_starttransferとtime_pretransferの差が大きい場合、サーバー側の処理（DB問い合わせやビジネスロジック）に時間がかかっていると判断できる。

まとめて計測する場合

複数回叩いて平均を見たい時は、ループで回してtime_totalだけ出す方が扱いやすい。

ターミナル
for i in $(seq 1 10); do
  curl "https://api.example.jp/controller/action" -o /dev/null -s -w "%{time_total}\n"
done

httpのみでhttpsを使わない環境ではtime_appconnectはtime_connectと同じ値になる（TLSハンドシェイクが発生しないため）。