curlの-wオプションを使うとHTTPリクエスト/レスポンスの様々なデータを表示することができます。が、ちょっと不可解な部分があったので調べてみました。
背景
ウェブアプリの簡単なテストのためcurlコマンドをよく使っていたのですが、-wオプションでちょっとしたパフォーマンス測定ができるらしいことを知りました。マニュアルを見ると、全体の処理時間（time_total）やTCPのコネクションにかかった時間（time_connect）などいくつかのデータを提供してくれますが、その中にtime_starttransferというのがあります。
time_starttransfer
The time, in seconds, it took from the start
until the first byte was just about to be trans-
ferred. This includes time_pretransfer and also
the time the server needed to calculate the
result.
ざっと訳すと、「開始から、最初のバイトがまさに転送されるときまでの秒数。time_pretransferと、サーバが結果の計算に必要だった時間も含む」となります。これならサーバのパフォーマンス測定に使えそうです。
しかし、POSTの場合はどうでしょうか？POSTのボディが大きい場合はリクエストの送信にも時間がかかります。その場合time_starttransferはリクエスト送信時間も含むのでしょうか？マニュアルの説明だけではよく分からず、ネット上にも詳細な説明はあまりないようなので調べてみることにしました。
-wオプションの使い方
その前にまずは-wオプションの使い方。curl -w <format>を使うと、各種データを標準出力に出すようになります。また、format中に%{変数名}を入れると、その部分が実際の値に置き換わります。例えば以下のようにすると、%{time_total}の部分が実際にかかったトータル時間に置き換わり、"total 0.003"などのように表示されます。なお、出力後に改行を入れてはくれないので、最後に\nを入れる方が良いでしょう。
$ curl -w "total %{time_toal}\n" http://localhostまた、<format>の先頭を@にすると、@以降の文字列で指定したファイルをフォーマット文字列として使うようになります。文字列が長い場合はこれを使うと良いでしょう。今回はformat.txtというファイルを作り、内容を以下のようにしました。
http_code %{http_code}\n
size_upload %{size_upload}\n
speed_upload %{speed_upload}\n
size_download %{size_download}\n
speed_download %{speed_download}\n
time_pretransfer %{time_pretransfer}\n
time_starttransfer %{time_starttransfer}\n
time_total %{time_total}\nなお、使える変数の一覧はcurlのmanページの-wオプションの項目にあります。
GETで試す
ということで早速試してみます。今回は時間の計測が目的であって実際にダウンロードされたコンテンツに興味はありません。-o /dev/nullとしてダウンロードしたデータは捨ててしまいましょう。また、-oを付けると自動的にアップロード/ダウンロード状況が表示されるようになりますが、これも邪魔なので-sを付けて抑制します。
$ curl -s -o /dev/null -w @format.txt http://localhost http_code 200 size_upload 0 speed_upload 0.000 size_download 11510 speed_download 3304622.000 time_pretransfer 0.002 time_starttransfer 0.003 time_total 0.003
GETメソッドで静的なコンテンツをダウンロードしています。localhostなので非常に高速、かつサイズもそれほど大きくないのでほぼ一瞬で終わっています。
重い処理の場合
ではサーバの処理が重くなったらどうでしょうか。以下のようなCGIスクリプトを用意してみました。最初にsleep 2としている部分が"重い処理"にあたるもので。2秒後にレスポンスを返すようになっています。
test1.cgi
#!/usr/bin/ruby sleep 2 print "Content-Type: text/plain\n\n" puts "ok"
$ curl -s -o /dev/null -w @format.txt http://localhost/~wagavulin/test1.cgi http_code 200 size_upload 0 speed_upload 0.000 size_download 3 speed_download 1.000 time_pretransfer 0.002 time_starttransfer 2.166 time_total 2.167
このように、starttransferが2秒ちょっとになっています。マニュアルにある「time_pretransferと、サーバが結果の計算に必要だった時間も含む」という説明に合っているようです。
POSTで試す（小さなデータ）
今度はPOSTを使ってみます。以下のようなスクリプトを作ってみました。recv_fileメソッドはリクエストのボディを受け取り、受け取ったバイト数を返します。最初にrecv_fileを呼び、その後2秒sleepしてからレスポンスを返します。
test2.cgi
#!/usr/bin/ruby def recv_file bytes = 0 while buf = $stdin.read(4096) bytes += buf.length end return bytes end bytes = recv_file sleep 2 print "Content-Type: text/plain\n\n" puts "received #{bytes.to_s}"
最初はsmall.txtという5バイトのファイルを使って試してみます。なお、--data-binaryなどといったデータ送信のためのオプションについては前回の記事を参考にして下さい。
$ curl -s -o /dev/null --data-binary @small.txt -w @format.txt http://localhost/~wagavulin/test2.cgi http_code 200 size_upload 5 speed_upload 2.000 size_download 11 speed_download 5.000 time_pretransfer 0.009 time_starttransfer 2.155 time_total 2.155
size_uploadが5になっています。また、time_starttransferもやはり2秒ちょっとです。
POSTで試す（大きなデータ）
今度は大きなデータを送ってみます。big.txtという、約60MBのファイルを用意しました。
$ curl -s -o /dev/null --data-binary @big.txt -w @format.txt http://localhost/~wagavulin/test2.cgi http_code 200 size_upload 61931520 speed_upload 24353647.000 size_download 18 speed_download 7.000 time_pretransfer 0.002 time_starttransfer 0.004 time_total 2.543
するとどういうわけか、time_starttransferが非常に小さな値になっています。2秒のsleepがあるので、レスポンスを返し始めるまでは最低2秒かかるはずです。なぜこんな小さな値になるのでしょうか？
ということで、原因調査のためまずは-vオプションで詳細な状況を見てみました。
$ curl -v -s -o /dev/null --data-binary @big.txt -w @format2.txt http://localhost/~wagavulin/test2.cgi * Trying 127.0.0.1... * Connected to localhost (127.0.0.1) port 80 (#0) > POST /~wagavulin/test2.cgi HTTP/1.1 > Host: localhost > User-Agent: curl/7.45.0 > Accept: */* > Content-Length: 61931520 > Content-Type: application/x-www-form-urlencoded > Expect: 100-continue > < HTTP/1.1 100 Continue } [16384 bytes data] * We are completely uploaded and fine < HTTP/1.1 200 OK 以下略
すると、リクエストヘッダに"Expect: 100-continue"があり、サーバもまず最初に100を返しています。さらにその後200を返しているのが分かります。このExpectヘッダはサーバがPOSTを受け入れ可能かをチェックするために使われています。仮にサーバがそのURL+パラメータではPOSTを受けれ入れない場合、大量のデータをPOSTしてからようやくエラーが返ってくるのでは無駄というものです。そこで、クライアントはリクエストに"Expect 100-continue"を入れます。サーバは、もし受け入れ可能であれば100を返し、そうでなければエラー（417）を返します。クライアントは100が返ったのを確認してからリクエストボディの送信を始めるようです。
curlはこの"100 Continue"のレスポンスが来た時間を持ってstarttransferとしており、そのため小さな値になっているのかもしれません。
Expectヘッダを抑制する
この予想の確認のため、Expectヘッダを使わないようにして試してみます。curlでは-Hオプションを使ってヘッダを指定することができますが、-H "Expect:"のようにするとヘッダ出力を抑制することができます。
$ curl -v -H "Expect:" -s -o /dev/null --data-binary @big.txt -w @format.txt http://localhost/~wagavulin/test2.cgi
* Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /~wagavulin/test2.cgi HTTP/1.1
> Host: localhost
> User-Agent: curl/7.45.0
> Accept: */*
> Content-Length: 61931520
> Content-Type: application/x-www-form-urlencoded
>
} [16384 bytes data]
* We are completely uploaded and fine
< HTTP/1.1 200 OK
< Date: Sat, 21 Nov 2015 11:31:14 GMT
< Server: Apache/2.4.7 (Ubuntu)
< Content-Length: 18
< Content-Type: text/plain
<
{ [18 bytes data]
* Connection #0 to host localhost left intact
http_code 200
size_upload 61931520
speed_upload 24889268.000
size_download 18
speed_download 7.000
time_pretransfer 0.001
time_starttransfer 0.001
time_total 2.488確かにExpectヘッダと100のレスポンスはなくなりました。が、やはりstarttransferは小さな値のままです。予想は外れてしまいました。
curlのソースを覗く
starttransferについて色々検索もしたのですが、あまり有益な情報が見つかりませでした。仕方ないのでソースを見てみることにしました。
すると、starttransferの時間を記録する箇所（Curl_pgrsTime(data, STARTTRANSFER);と書かれた箇所）、がlib/transfer.cに2箇所ありました。それぞれreadwrite_upload()関数とreadwrite_data()関数です。この2つのいずれかが最初に呼ばれた段階でstarttransferの値が決まるようです。
また、readwrite_upload()関数のコメントに"Send data to upload to the server, when the socket is writable."と書かれていました。つまり、starttransferはレスポンスを受け取るときだけでなく、データをアップロードし始めるタイミングでも記録されるようです。
そして、このreadwrite_upload()はどうやらPOSTするファイルのサイズが1025バイト以上のときに呼ばれるらしいことが分かりました。
再び実験
ということで、アップロードするファイルのサイズを変えて実験してみます。1024.txt, 1025.txtというファイルを作りました。名前のとおり、サイズはそれぞれ1024, 1025バイトです。これを先ほどのtest2.cgiにPOSTします。すると思ったとおり、1024バイトか1025バイトかによってtime_starttransferの値が大きく変わりました。
$ curl -s -o /dev/null --data-binary @1024.txt -w @format.txt http://localhost/~wagavulin/test2.cgi http_code 200 size_upload 1024 speed_upload 474.000 size_download 14 speed_download 6.000 time_pretransfer 0.005 time_starttransfer 2.159 time_total 2.160 $ curl -s -o /dev/null --data-binary @1025.txt -w @format.txt http://localhost/~wagavulin/test2.cgi http_code 200 size_upload 1025 speed_upload 473.000 size_download 14 speed_download 6.000 time_pretransfer 0.002 time_starttransfer 0.004 time_total 2.165
time_starttransferの仕様
ということで結論です。curlのtime_starttransferの値は以下のようになっているようです。
- GETのようにリクエストのボディがない => レスポンスを受け取り始めた時間
- POSTのようにリクエストのボディがある
- 指定したファイルのサイズが1024バイト以下 => レスポンスを受け取り始めた時間
- 指定したファイルのサイズが1025バイト以上 => リクエストボディを送り始めた時間
なぜこのような仕様になっているのでしょうか？何か意図があるのかもしれませんが、個人的には分かりにくいし使いにくいと思います。POSTのサイズが大きい場合はstarttransferはほぼ0に近い値になるため、あまり意味がないように思います。
速度を使って計算してみる
とここで、speed_uploadとspeed_downloadというパラメータあるのを思い出しました。マニュアルによれば、アップロード/ダウンロードにかかった平均時間（bytes/second）のようです。アップロード/ダウンロードサイズも分かっているので、割り算をすれば時間も分かるはずです。
実験のため今度は以下のようなCGIスクリプトを用意しました。
test3.cgi
#!/usr/bin/ruby def recv_file bytes = 0 while buf = $stdin.read(4096) bytes += buf.length end return bytes end def send_data(kbytes) str_1k = 'a' * 1023 + "\n" for i in 1..kbytes print str_1k end end bytes = recv_file sleep 2 print "Content-Type: text/plain\n\n" send_data(1024 * 100)
send_data()は、指定したサイズ（KBytes）のデータを出力します（つまりレスポンスボディとして返します）。recv_fileでリクエストをすべて受け取り、その後2秒sleepした後、100MBのデータをレスポンスとして返します。
これと先ほどのbig.txtを使って実験です。
$ curl -s -o /dev/null --data-binary @big.txt -w @format.txt http://localhost/~wagavulin/test3.cgi http_code 200 size_upload 61931520 speed_upload 20495351.000 size_download 104857600 speed_download 34701123.000 time_pretransfer 0.001 time_starttransfer 0.003 time_total 3.022
計算してみると以下のようになります。
- アップロード時間: 61931520 / 20495351.000 = 3.0217 (秒)
- ダウンロード時間: 104857600 / 34701123.000 = 3.0217 (秒)
どういうわけかどちらもほぼ同じ値で、かつtime_totalとほぼ同じです。なぜこうなるのか深く追ってはいませんが、ともかくこれではパフォーマンス測定には使えません。さて困りました。
ということで次回に続く。
