Webサーバのベンチマーク結果をレスポンスタイムの時系列データとして計測する簡単な方法

単純に特定のURLに対してミドルウェアの性能を計測したい場合などには、今でもabやwrk、h2loadのようなシナリオベースではないシンプルなベンチマークはとても有用です。

一方で、最近ではgatlingやtsungといった、豊富な機能やリッチな計測結果を取得できるベンチマークソフトウェアも豊富になってきました。

ただ、例えば、単に「Webサーバのベンチマーク結果をレスポンスタイムの時系列データとして計測したい」時に、僕のようなめんどくさがりの人間はcliで適当にオプションを渡して1回の実行でシュシュシュっと取りたいものですが、それができるツールが見当たらず、うーむ、gatlingやtsuningでやるかなぁとおもっていたところ、なんとApache Bench(ab)で簡単にシュシュシュっとできてしまうことに気づいたのでした。

ということでその方法を紹介します。例えば以下のような要件の時にはピッタリでしょう。

abやwrkのようなベンチマークの計測で十分なワークロード
秒単位でのレスポンスタイムの時系列データ程度の粒度の計測で十分
cliでシュシュシュっとやりたい

この場合にはabを使えばすぐにできます。

gnuplotアウトプットのデータを使う

abコマンドは、-gオプションによってgnuplot用のデータを出力できます。これは、1万リクエストすれば、10000個分のconnectionタイム、processingタイム、などを取得することができます。例えば、以下のようなコマンドを実行すると、

ab -l -g result.tsv -k  -c 100 -n 100000 http://example.jp/

result.tsvに以下のような内容のデータが10万行生成されます。

starttime       seconds ctime   dtime   ttime   wait
Sat May 27 19:02:05 2017        1495879325      0       17      17      14
Sat May 27 19:02:05 2017        1495879325      0       17      17      15
Sat May 27 19:02:05 2017        1495879325      0       17      17      14
Sat May 27 19:02:05 2017        1495879325      0       18      18      15
Sat May 27 19:02:05 2017        1495879325      0       18      18      16
Sat May 27 19:02:05 2017        1495879325      0       18      18      16

このデータのctimeはconnectionにかかった時間、dtimeはリクエスト処理にかかった時間、ttimeはctimeとdtimeの合計、waitはよくわかりません。が、概ねabの結果と照らし合わせると、ttimeがトータルのレスポンスタイムとして理解すると良いでしょう。

レスポンスタイムの時系列データへ変換

このgnuplotのデータは、時系列にはならばずttimeでソートされているので、普通に使うとよくわからないデータになってしまいます。また、それぞれのデータの時刻の値は秒単位でしか記録されていないので、同一時刻のものの中でmsec単位でのソートができません（これはabのコードをいじったらいいだけなので必要になったらやる）。

なので、同一時刻でのctimeやdtimeの値の平均をとって、秒の粒度のでの時系列データに変換します。そのためのコードはシュシュシュっと例えば以下のように書くと良いでしょう。シェルでもなんでも良いと思います。

#!/usr/bin/env ruby

# Sat May 27 17:56:34 2017        1495875394      0       773     773     772
# Sat May 27 17:56:39 2017        1495875399      0       773     773     765
# Sat May 27 17:56:18 2017        1495875378      0       773     773     771
# Sat May 27 17:56:19 2017        1495875379      0       774     774     771
# Sat May 27 17:56:19 2017        1495875379      0       774     774     770
# Sat May 27 17:56:19 2017        1495875379      0       774     774     772

smooth_data = []

$stdin.each_line do |l|
  new = l.split("\t")
  next if new[0] == "starttime"
  old = smooth_data[-1]
  if old && old[0] == new[0]
    smooth_data[-1] = [old[0],
                       old[1],
                       (old[2].to_i + new[2].to_i) / 2,
                       (old[3].to_i + new[3].to_i) / 2,
                       (old[4].to_i + new[4].to_i) / 2,
                       (old[5].to_i + new[5].to_i) / 2]
  else
    smooth_data << [new[0],
                    new[1],
                    new[2].to_i,
                    new[3].to_i,
                    new[4].to_i,
                    new[5].to_i]
  end
end

smooth_data.each do |d|
  puts "#{d[0]}\t#{d[2]}\t#{d[3]}\n"
end

この上で、以下のように時刻でsortしたgnuplotのデータをこのようなスクリプトに食わすと、

sort result.tsv | ./ab-data-smooth.rb
Sun May 28 13:32:19 2017        0       97
Sun May 28 13:32:20 2017        0       98
Sun May 28 13:32:21 2017        0       242
Sun May 28 13:32:22 2017        0       98
Sun May 28 13:32:23 2017        0       93
Sun May 28 13:32:24 2017        0       95
Sun May 28 13:32:25 2017        0       98
Sun May 28 13:32:26 2017        0       96
Sun May 28 13:32:27 2017        0       98
Sun May 28 13:32:28 2017        0       98
Sun May 28 13:32:29 2017        0       386
Sun May 28 13:32:30 2017        0       361
Sun May 28 13:32:31 2017        0       373
Sun May 28 13:32:32 2017        0       340
Sun May 28 13:32:33 2017        0       342
Sun May 28 13:32:34 2017        0       316
Sun May 28 13:32:35 2017        0       373
Sun May 28 13:32:36 2017        0       409
Sun May 28 13:32:37 2017        0       391

こんな感じで時刻の秒単位の粒度でのレスポンスタイム時系列データに変換されたtsvデータが得られますので、これを何かでシュシュっとグラフ化しましょう。すると以下のようなグラフが得られます。

f:id:matsumoto_r:20170528144746p:plain