どうも、ベンチマークおじさん、可視化おじさんの かっぱ(@inokara) です。
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 は…
上記のようにレスポンスタイムが表示されました！
やったー。
まとめ
siege が出力するログではレスポンスタイムは実行時間の平均値しか取得出来ませんでしたが、標準出力から取得することでより細かいレスポンスタイムが取得することが出来ました。また、fluentd と Graphite を利用することでお手軽に可視化まで行うことが出来ました。
毎回のことながら fluentd やそのプラグインの作者の方には足を向けて寝られません。。。
元記事はこちらです。
「siege の標準出力に出力されるレスポンスタイムを fluentd を経由して Graphite で可視化する」
