Neinvalli

研究テーマは ”IT 環境でのリソース最適化” です

curl を利用してウェブサーバー側の処理時間を推計する

curl を利用してウェブサーバー側の処理時間を推計しようというのが今回のテーマです。

前回の記事 ウェブでのリバースプロキシ導入目的は消費メモリ量を抑えるため ではこのスクリプトを利用してメジャーなサイトの速度を計測しました。

以下の例は前回の記事の test.php に対して計測スクリプトを実行した結果です。

[root @st-webclient001 ~]# ./check-speed.sh 'http://10.1.0.2/test.php'
response_size:                             36263  bytes
msec_namelookup:                           0      msec
msec_connect:                              50     msec
msec_ssl_handshake_overhead:               0      msec
msec_client_transfer_request(estimated):   25     msec
msec_server_generate_response(estimated):  151    msec
msec_server_transfer_response(estimated):  76     msec
msec_total:                                302    msec

　

curl の -w オプション

curl には -w, --write-out <format> というオプションがあります。

format の部分では、curl の変数の使うことができ、これを利用して curl の各ステップでかかった時間を表示することが可能です。

例えば、下記のような使い方です。

# curl -s -o /dev/null -w 'code:%{http_code} size_download:%{size_download} time_total:%{time_total}\n' "https://www.google.co.jp/"
code:200 size_download:10897 time_total:0.502

今回使うのは下記の変数です。

  size_download  The total amount of bytes that were downloaded.

  time_connect   The time, in seconds, it took from the start until the TCP connect to the remote host (or proxy) was completed.

  time_namelookup
                 The time, in seconds, it took from the start until the name resolving was completed.

  time_pretransfer
                 The  time, in seconds, it took from the start until the file transfer was just about to begin. This includes all pre-transfer commands and negotiations that are specific to the particu-
                 lar protocol(s) involved.

  time_starttransfer
                 The  time,  in seconds, it took from the start until the first byte was just about to be transferred. This includes time_pretransfer and also the time the server needed to calculate the
                 result.

  time_total     The total time, in seconds, that the full operation lasted. The time will be displayed with millisecond resolution.

ざっと挙げると下記のとおりです。

  • size_download - ダウンロードしたバイト数
  • time_namelookup - 開始から DNS 名前解決完了までの時間
  • time_connect - 開始からリモートホストへの TCP コネクションが完了するまでの時間
  • time_pretransfer - 開始からデータ転送開始までの時間
  • time_starttransfer - 開始から最初の 1バイトが転送されるまでの時間
  • time_total - トータルの時間

これだけだと意味がわかりません。

　

tcpdump の結果と比較

tcpdump の結果と比較した限りでは下記のとおりです

  • size_download - ダウンロードしたバイト数
  • time_namelookup - 開始から DNS 名前解決完了までの時間
  • time_connect - 開始から TCP 3ウェイハンドシェイクの SYN -> SYN/ACK -> ACK の 3つ目の ACK を送信した瞬間までの時間
  • time_pretransfer - 開始からクライアントが HTTP リクエストを送信する瞬間までの時間
  • time_starttransfer - 開始からクライアントがサーバー側からの最初の 1バイトを受信した瞬間までの時間
  • time_total - 開始から、TCP コネクション終了に FIN をクライアントが送信した瞬間までの時間
[root @st-webclient001 speed-tools]# ./check-speed.sh 'http://10.1.0.2/test.php'
---- curl raw variable values ----
code:                200
size_download:       36263
time_namelookup:     0.000
time_connect:        0.051
time_appconnect:     0.000
time_pretransfer:    0.051
time_starttransfer:  0.251
time_total:          0.352

---- calculated each phase times ----
response_size:                             36263  bytes
msec_namelookup:                           0      msec
msec_connect:                              51     msec
msec_ssl_handshake_overhead:               0      msec
msec_client_transfer_request(estimated):   25     msec
msec_server_generate_response(estimated):  149    msec
msec_server_transfer_response(estimated):  126    msec
msec_total:                                351    msec

[root @st-webclient001 ~]# tcpdump -nnn -i enp0s8 '((dst 10.1.0.2) and (dst port 80)) || ((src 10.1.0.2) and (src port 80))'
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp0s8, link-type EN10MB (Ethernet), capture size 262144 bytes
22:01:27.341618 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [S], seq 2615431876, win 29200, options [mss 1460,sackOK,TS val 2832563 ecr 0,nop,wscale 9], length 0
22:01:27.392671 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [S.], seq 77093785, ack 2615431877, win 28960, options [mss 1460,sackOK,TS val 2863731 ecr 2832563,nop,wscale 9], length 0
22:01:27.392699 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 1, win 58, options [nop,nop,TS val 2832576 ecr 2863731], length 0
22:01:27.392849 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [P.], seq 1:420, ack 1, win 58, options [nop,nop,TS val 2832576 ecr 2863731], length 419: HTTP: GET /test.php HTTP/1.1
22:01:27.443610 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [.], ack 420, win 59, options [nop,nop,TS val 2863744 ecr 2832576], length 0
22:01:27.592097 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [.], seq 1:11585, ack 420, win 59, options [nop,nop,TS val 2863781 ecr 2832576], length 11584: HTTP: HTTP/1.1 200 OK
22:01:27.592118 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 11585, win 103, options [nop,nop,TS val 2832626 ecr 2863781], length 0
22:01:27.592297 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [.], seq 11585:14481, ack 420, win 59, options [nop,nop,TS val 2863781 ecr 2832576], length 2896: HTTP
22:01:27.592306 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 14481, win 114, options [nop,nop,TS val 2832626 ecr 2863781], length 0
22:01:27.642365 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [.], seq 14481:20273, ack 420, win 59, options [nop,nop,TS val 2863794 ecr 2832626], length 5792: HTTP
22:01:27.642380 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 20273, win 137, options [nop,nop,TS val 2832638 ecr 2863794], length 0
22:01:27.693085 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [P.], seq 20273:26065, ack 420, win 59, options [nop,nop,TS val 2863806 ecr 2832638], length 5792: HTTP
22:01:27.693106 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 26065, win 159, options [nop,nop,TS val 2832651 ecr 2863806], length 0
22:01:27.693373 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [P.], seq 26065:36485, ack 420, win 59, options [nop,nop,TS val 2863806 ecr 2832638], length 10420: HTTP
22:01:27.693384 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 36485, win 200, options [nop,nop,TS val 2832651 ecr 2863806], length 0
22:01:27.693491 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [F.], seq 420, ack 36485, win 200, options [nop,nop,TS val 2832651 ecr 2863806], length 0
22:01:27.744300 IP 10.1.0.2.80 > 10.101.0.4.44605: Flags [F.], seq 36485, ack 421, win 59, options [nop,nop,TS val 2863819 ecr 2832651], length 0
22:01:27.744312 IP 10.101.0.4.44605 > 10.1.0.2.80: Flags [.], ack 36486, win 200, options [nop,nop,TS val 2832664 ecr 2863819], length 0
^C

　

わかりやすいように図にしました。

f:id:neinvalli:20171030000208p:plain

ここでは SSL を使用していないため、SSL のハンドシェイクのオーバーヘッドと DNS 名前解決の時間は入っていません。

図の中に書いてしまったのですが、特筆事項は下記のとおりです。

  • time_connect は SYN -> SYN/ACK -> SYN を送信直後の時間なので、実質はラウンドトリップタイムだと考えることができます。
  • HTTP Request の送信時間はラウンドトリップタイムの半分と考えることができます。
  • 図を見ていただくとわかりやすいかと思いますが、time_starttransfer - time_pretransfer には HTTP リクエストと HTTP レスポンスを送信する時間が含まれるため、この数字からラウンドトリップタイムを引くことでサーバーがレスポンスを生成するのにかかった時間を推計できます
  • time_total - time_starttransfer に HTTP レスポンスの1パケット目の送信時間を加算するとレスポンスの転送時間が推計できます。

　

スクリプトのソースコード

#!/bin/bash


# Usage
# 
# ./check-speed.sh 'http://example.com/'
# 
# ./check-speed.sh -tsv 'http://example.com/'
#
# ./check-speed.sh -ltsv 'http://example.com/'
# 

if echo "$1" | egrep -q '^-';  then
    case "$1" in
        "-tsv") mode="tsv";;
        "-ltsv") mode="ltsv";;
    esac
    shift;
fi


url="$1"


data=$(curl -s \
 -H 'accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8' \
 -H 'accept-encoding:gzip, deflate, br' \
 -H 'accept-language:en-US,en;q=0.8' \
 -H 'cache-control:no-cache' \
 -H 'pragma:no-cache' \
 -H 'upgrade-insecure-requests:1' \
 -H 'user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/61.0.3163.79 Chrome/61.0.3163.79 Safari/537.36' \
 -m 15 \
 -o /dev/null \
 -w 'code:%{http_code} size_download:%{size_download} time_namelookup:%{time_namelookup} time_connect:%{time_connect} time_appconnect:%{time_appconnect} time_pretransfer:%{time_pretransfer} time_starttransfer:%{time_starttransfer} time_total:%{time_total} \n' \
 "$url")

if [[ "$?" != 0 ]];  then # it means prior curl command failed
    echo "curl failed"
    exit 2
fi

size_download=$(echo "$data" | perl -ne 's|^.*size_download:([.0-9]+) .*$|$1|; print;')
msec_time_namelookup=$(echo "$data" | perl -ne 's|^.*time_namelookup:([.0-9]+) .*$|$1|; print ($_ * 1000);')
msec_time_connect=$(echo "$data" | perl -ne 's|^.*time_connect:([.0-9]+) .*$|$1|; print ($_ * 1000);')
msec_time_pretransfer=$(echo "$data" | perl -ne 's|^.*time_pretransfer:([.0-9]+) .*$|$1|; print ($_ * 1000);')
msec_time_starttransfer=$(echo "$data" | perl -ne 's|^.*time_starttransfer:([.0-9]+) .*$|$1|; print ($_ * 1000);')
msec_time_total=$(echo "$data" | perl -ne 's|^.*time_total:([.0-9]+) .*$|$1|; print ($_ * 1000);')

# debug
# echo "$msec_time_namelookup $msec_time_connect $msec_time_pretransfer $msec_time_starttransfer $msec_time_total"

response_size=$size_download
msec_namelookup=$msec_time_namelookup
msec_connect=$(($msec_time_connect - $msec_time_namelookup))
msec_ssl_handshake_overhead=$(($msec_time_pretransfer - $msec_time_connect))
msec_request_to_first_byte=$(($msec_time_starttransfer - $msec_time_pretransfer))
msec_client_transfer_request=$(($msec_connect / 2))
msec_server_generate_response=$(($msec_request_to_first_byte - $msec_connect))
msec_server_transfer_response=$(($msec_time_total - $msec_time_starttransfer + (msec_connect / 2)))
msec_total=$(($msec_namelookup + $msec_connect + $msec_ssl_handshake_overhead + $msec_client_transfer_request + $msec_server_generate_response + $msec_server_transfer_response))


case "$mode" in
    "tsv")
        echo -e "$response_size\t$msec_namelookup\t$msec_connect\t$msec_ssl_handshake_overhead\t$msec_client_transfer_request\t$msec_server_generate_response\t$msec_server_transfer_response\t$msec_total";;
    "ltsv")
        echo -e "response_size:$response_size\tmsec_namelookup:$msec_namelookup\tmsec_connect:$msec_connect\tmsec_ssl_handshake_overhead:$msec_ssl_handshake_overhead\tmsec_client_transfer_request:$msec_client_transfer_request\tmsec_server_generate_response:$msec_server_generate_response\tmsec_server_transfer_response:$msec_server_transfer_response\tmsec_total:$msec_total";;
    *)
        echo "---- curl raw variable values ----"
        echo "$data" | perl -ne 's| |\n|g; s|:|: |g; print;' | column -t
        echo
        echo "---- calculated each phase times ----"
        echo "response_size: $response_size bytes
msec_namelookup: $msec_namelookup msec
msec_connect: $msec_connect  msec
msec_ssl_handshake_overhead: $msec_ssl_handshake_overhead msec
msec_client_transfer_request(estimated): $msec_client_transfer_request msec
msec_server_generate_response(estimated): $msec_server_generate_response msec
msec_server_transfer_response(estimated): $msec_server_transfer_response msec
msec_total: $msec_total msec" | column -t;;
esac

　

実行結果サンプル

$ ./check-speed.sh 'http://example.com/'
---- curl raw variable values ----
code:                200
size_download:       606
time_namelookup:     0.060
time_connect:        0.222
time_appconnect:     0.000
time_pretransfer:    0.222
time_starttransfer:  0.391
time_total:          0.391

---- calculated each phase times ----
response_size:                             606  bytes
msec_namelookup:                           60   msec
msec_connect:                              162  msec
msec_ssl_handshake_overhead:               0    msec
msec_client_transfer_request(estimated):   81   msec
msec_server_generate_response(estimated):  7    msec
msec_server_transfer_response(estimated):  81   msec
msec_total:                                391  msec

TCP コネクションの部分でインターネット上の途中経路でパケットロスや遅延があった場合に、 ラウンドトリップタイムが大きくなってしまった場合に、msec_server_generate_response がマイナスになってしまうケースがあるので、その点だけ注意点です。 複数回実行し、極端な数字を排除した上で平均値を出すのが適切かと思います。