どうも、ベンチマークおじさん、可視化おじさんの かっぱ(@inokara) です。

siege の標準出力には何が出力される?

siege が標準出力に出力する表示

内容的には以下のようなものが出力されています。

  • リクエストバージョン
  • ステータスコード
  • レスポンスタイム(秒)
  • レスポンス容量(バイト)
  • リクエストメソッド
  • リクエストパス

今回、出力されるレスポンスタイムを Graphite で可視化してみたいと思います。

可視化への道のり

標準出力を CSV 形式に

特に難しいことはありません .siegerc に以下を記載しておけば標準出力が CSV 形式になります。

csv = true

上記の設定を行った後に siege を実行すると以下のように標準出力に CSV 形式で出力されます。

HTTP/1.1,200,  0.43,   2906,/index.html,0,2014-09-03 09:05:07

ただし…

この標準出力は上図のように青色で出力され、ファイルにリダイレクトすると以下のようにエスケープ文字がうざい感じになってしまいます…

^[[0;34mHTTP/1.1,200,  0.44,   2906,/index.html,0,2014-09-03 07:08:32^[[0m

このエスケープ文字は力技ですが、以下のようにして sed コマンドを駆使して置換してしまいます。

/usr/local/bin/siege -c 250 -r 1 --log=test.log -f url.txt | sed -r "s/x1B[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]//g" > /tmp/siege_stdout_log

置換して出力された CSV ファイルを以下のようにして fluentd で処理してしまいます。
siege-metrics.conf

<source>
  type tail
  path /tmp/siege_stdout_log
  pos_file /tmp/siege_stdout_log.pos
  tag siege.stdout
  # output example => HTTP/1.1,200,  0.43,   2906,/index.html,0,2014-09-03 09:05:07
  format /(?<Request_version>[^ ]*),(?<Response_code>[^ ]*),s{0,}(?<Response_time>d+(.d+)?),s{0,}(?<Response_bytes>d+(.d+)?),(?<Request_path>[^ ]*),(?<Result>[^ ]*),(?<Date_time>(d{4})-(d{2})-(d{2}) (d{2}:)(d{2}):(d{2}))/
</source>

<match siege.stdout>
  type copy
  <store>
    type forward
    <server>
      host xxx.xxx.xxx.xxx
      port 24224
    </server>
  </store>
  <store>
    type file
    path /tmp/debug
  </store>
</match>

fluent-plugin-graphite の処理

以下のように設定します。

siege-graphite.conf

<source>
  type forward
  port 24224
  bind 0.0.0.0
</source>

<match siege.stdout>
  type copy
  <store>
    type stdout
  </store>
  <store>
    type graphite
    host localhost
    port 2003
    tag_for prefix
    name_keys Response_time
  </store>
</match>

そして Graphite

メトリクスの取得間隔を調整

インストール仕立ての Graphite だとメトリクスの収集間隔は 60 秒に定義されています(環境により異なるかもしれませんが…)ので /etc/carbon/storage-schemas.conf を以下のように修正して carbon-cache を再起動します。

[default_1min_for_1day]
pattern = .*
retentions = 1s:21d

whisper データベースのリサイズ

既にメトリクスの蓄積を行っている場合には以下のように実行して Whisper のデータベースをリサイズしてしまいます。

whisper-resize Response_time.wsp 1s:21d

リサイズされたかは以下のように確認します。

whisper-info Response_time.wsp

maxRetention: 1814400 であることを確認します。

そして結果

以下のように siege を実行。

siege -c 250 -r 1 --time=3M --log=test.log -f url.txt | sed -r "s/x1B[([0-9]{1,2}(;[0-9]{1,2})?)?[m|K]//g" > /tmp/siege_stdout_log

siege の実行結果は下記のように表示されました。

Lifting the server siege...      done.

Transactions:                  53199 hits
Availability:                 100.00 %
Elapsed time:                 179.93 secs
Data transferred:              61.82 MB
Response time:                  0.35 secs
Transaction rate:             295.66 trans/sec
Throughput:                     0.34 MB/sec
Concurrency:                  102.12
Successful transactions:       53199
Failed transactions:               0
Longest transaction:            0.88
Shortest transaction:           0.01

そして、肝心の Graphite は…
Graphite による seige の出力結果 (レスポンスタイムの出力)

上記のようにレスポンスタイムが表示されました!

やったー。

まとめ

siege が出力するログではレスポンスタイムは実行時間の平均値しか取得出来ませんでしたが、標準出力から取得することでより細かいレスポンスタイムが取得することが出来ました。また、fluentd と Graphite を利用することでお手軽に可視化まで行うことが出来ました。

毎回のことながら fluentd やそのプラグインの作者の方には足を向けて寝られません。。。

元記事はこちらです。
siege の標準出力に出力されるレスポンスタイムを fluentd を経由して Graphite で可視化する