🚅

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

2021/01/21に公開

Linux

tech

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 形式で出力できます。

出力される全ての項目は下記の通りです。
今回確認したいレスポンスタイム以外にも、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 などで紹介されています。

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

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)を用いて計測するのは場合によっては適切ではないということです。
1 つの例として 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,

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

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

終わりに

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

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

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

curlの便利なoption (-w)

各項目の定義

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

終わりに

Discussion