理解しておきたいcurlの --write-out オプション

6 min read読了の目安(約6000字

HTTP Requestのレスポンスタイムの計測方法について調べていて、curlのoption( -w, --write-out )について知りました。
備忘録として、調べた内容を簡単にまとめていきます。

環境は下記の通りです。

  • OS: macOS Catalina 10.15.4
  • curl: 7.74.0 (x86_64-apple-darwin19.6.0)

curlの便利なoption (-w)

curlには -w, --write-out というoptionがあります。

# curl --help
Usage: curl [options...] <url>
     --abstract-unix-socket <path> Connect via abstract Unix domain socket
     --alt-svc <file name> Enable alt-svc with this cache file

...

 -w, --write-out <format> Use output FORMAT after completion

通常、オプションを指定せずにcurlを使うと、Response Bodyが出力されます。

$ curl https://www.google.com
<!doctype html><html itemscope="" itemtype="http://schema.org/WebPage" lang="ja"><head><meta content="&#19990;&#30028;&#20013;&#12398;&#12354;&#12425;&#12422;&#12427;&#24773;&#22577;&#12434;&#26908;&#32034;&#12377;&#12427;&#12383;&#12417;&#12398;&#12484;&#12540;&#12523;&#12434;&#25552;&#20379;&#12375;&#12390;&#12356;&#12414;&#12377;&#12290;&#12373;&#12414;&#12374;&#12414;&#12394;&#26908;&#32034;&#27231;&#33021;&#12434;&#27963;&#29992;&#12375;&#12390;&#12289;&#12362;&#25506;&#12375;&#12398;&#24773;&#22577;&#12434;&#35211;&#12388;&#12369;&#12390;&#12367;&#12384;&#12373;&#12356;&#12290;" name="description"><meta content="noodp" name="robots"><meta content="text/html; ...

-w のoptionはフォーマットを指定してHTTP Requestの詳細結果の出力が可能で、下記のように利用します。
(-s は進捗の表示を無効化する、-o /dev/null は時間計測に不要なレスポンスボディを捨てるためにオプションを指定しています。)

$ curl -s -o /dev/null -w '%{time_starttransfer}\n%{time_total}\n' https://www.google.com
188123

curlのversion7.70.0からは、フォーマットの指定部分で -w '%{json}' のようにして取得できる全ての項目をjson形式で出力できます。

https://github.com/curl/curl/commit/04c03416e68fd635a15cae8201872f5c29fdcca8

出力される全ての項目は下記の通りです。
今回確認したいレスポンスタイム以外にも、size_header (レスポンスヘッダーのサイズ)や size_request (HTTP Requestの総バイト数)などが含まれています。

$ curl -s -o /dev/null -w '%{json}' https://www.google.com
{"url_effective":"https://www.google.com/","method":"GET","http_code":200,"response_code":200,"num_headers":13,"http_connect":0,"time_total":0.194313,"time_namelookup":0.004821,"time_connect":0.016388,"time_appconnect":0.098470,"time_pretransfer":0.098655,"time_starttransfer":0.194101,"size_header":878,"size_request":76,"size_download":13925,"size_upload":0,"speed_download":71778,"speed_upload":0,"content_type":"text/html; charset=ISO-8859-1","num_connects":1,"time_redirect":0.000000,"num_redirects":0,"ssl_verify_result":0,"proxy_ssl_verify_result":0,"filename_effective":"/dev/null","remote_ip":"172.217.24.132","remote_port":443,"local_ip":"192.168.11.6","local_port":51667,"http_version":"2","scheme":"HTTPS","curl_version":"libcurl/7.74.0 (SecureTransport) OpenSSL/1.1.1i zlib/1.2.11 brotli/1.0.9 zstd/1.4.8 libidn2/2.3.0 libssh2/1.9.0 nghttp2/1.42.0 librtmp/2.3"}

その中でレスポンスタイムに関係する箇所は下記の通りです。
下記の例では、最終的なレスポンスタイムで約0.19秒かかったことがわかります。)

{
    "time_total":0.194313,
    "time_namelookup":0.004821,
    "time_connect":0.016388,
    "time_appconnect":0.098470,
    "time_pretransfer":0.098655,
    "time_starttransfer":0.194101,
}

各項目の定義

出力されている各項目の説明はman curlで確認するかもしくは下記のBlogなどで紹介されています。

https://blog.cloudflare.com/a-question-of-timing/

いずれもリクエスト開始からの時間となっており、下記のような定義になっています。

  • time_namelookup: DNSでの名前解決が完了するまでの時間
  • time_connect: TCP three-way handshakeにおいてClient側がACKを受け取るまでの時間
  • time_appconnect: TLSのhandshakeが完了するまでの時間
  • time_pretransfer: Clinet側から最初のbyteが転送される(=データ転送開始)までの時間
  • time_starttransfer: Server側からResponseとして最初のbyteを受け取るまでの時間(TTFB, Time To First Byte)
  • time_total: トータルの経過時間

上記の定義を踏まえて下記の計測結果を見ると、より理解しやすいかと思います。

// $ curl -s -o /dev/null -w '%{json}' https://www.google.com の結果
{
    ...
    "time_total":0.194313,
    "time_namelookup":0.004821,
    "time_connect":0.016388,
    "time_appconnect":0.098470,
    "time_pretransfer":0.098655,
    "time_starttransfer":0.194101,
    ...
}

レスポンスタイム計測の実験

ここでの注意点として、レスポンスタイムに関してトータルの経過時間(time_total)を用いて計測するのは場合によっては適切ではないということです。
一つの例としてResponse bodyに含まれるデータ量によってレスポンスのトータルの時間は大きく変動します。

極端な例として、ソフトウェアのダウンロードを例に検証を行います。
先ほどと同様に--write-out '%{json}'のoptionを付与して計測します。

$ curl -o vim.tar.bz2 -s --write-out '%{json}' http://ftp2.jp.vim.org/pub/vim/unix/vim-8.1.tar.bz2
{"url_effective":"http://ftp2.jp.vim.org/pub/vim/unix/vim-8.1.tar.bz2","method":"GET","http_code":200,"response_code":200,"num_headers":7,"http_connect":0,"time_total":36.002026,"time_namelookup":0.769248,"time_connect":0.786111,"time_appconnect":0.000000,"time_pretransfer":0.786162,"time_starttransfer":0.836736,"size_header":231,"size_request":107,"size_download":2955185,"size_upload":0,"speed_download":82083,"speed_upload":0,"content_type":"application/x-bzip2","num_connects":1,"time_redirect":0.000000,"num_redirects":0,"ssl_verify_result":0,"proxy_ssl_verify_result":0,"filename_effective":"vim.tar.bz2","remote_ip":"203.178.132.80","remote_port":80,"local_ip":"192.168.11.6","local_port":54133,"http_version":"1.1","scheme":"HTTP","curl_version":"libcurl/7.74.0 (SecureTransport) OpenSSL/1.1.1i zlib/1.2.11 brotli/1.0.9 zstd/1.4.8 libidn2/2.3.0 libssh2/1.9.0 nghttp2/1.42.0 librtmp/2.3"}%    

上記からレスポンスタイムの部分を抽出したものが下記になります。
time_starttransfer ~ time_total間の経過時間が大幅に増加していることがわかります。

これはサーバー側から送信されるデータ量が大きいため、データ転送に時間がかかっている事実を表しています。
サーバー側のResponse Timeの短縮を目的に時間計測を行うとして、time_totalではなくデータ量に関係ないtime_starttransfer(Time To First Byte)が計測に適切であることがわかるかと思います。

"time_namelookup":0.769248,
"time_connect":0.786111,
"time_appconnect":0.000000,
"time_pretransfer":0.786162,
"time_starttransfer":0.836736,
———
"time_total":36.002026,

https://developer.mozilla.org/en-US/docs/Glossary/time_to_first_byte

また、例として下記の指標などもレスポンスタイムのボトルネックを見つけるために利用されることが多いです。

  • DNSの名前解決までの時間(time_namelookup)
  • time_starttransfertime_pretransferの差分(=リクエスト送信からレスポンスを返し始めるまでの時間、レスポンス生成までの時間)

終わりに

以上、curlの--write-outオプションについて簡単に説明しました。
curl単体でもResponse Timeの計測・ボトルネックの洗い出しに十分に利用できることがわかっていただけたかと思います。

apache bench(ab)などのベンチマークツールなどもありますが、セットアップ不要ですぐに実行できるという点ではcurlの方がとっつきやすいです。

https://httpd.apache.org/docs/2.4/programs/ab.html

利用用途に応じて適切に使い分けて、より良い計測を行っていきましょう。