読者です 読者をやめる 読者になる 読者になる

curlコマンドによるウェブアプリのパフォーマンス測定 (1) time_starttransferの仕様

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とほぼ同じです。なぜこうなるのか深く追ってはいませんが、ともかくこれではパフォーマンス測定には使えません。さて困りました。

ということで次回に続く。