2015年9月28日12時8分: 作者の@tkuchikiさんからコメントで指摘頂いた部分を修正いたしました. ありがとうございます!

アクセスログの解析ツールとして, YAPC::Asia 2015で@kazeburoさんがkataribeを紹介していました(ISUCONの勝ち方)が, ISUCON 5直前にalpというツールがリリースされていて, 今回はこれを使って予選に挑戦しました.

...というわけで, インストール方法や使い方等, チームメンバーに共有するために作ったドキュメントをサルベージしておくことにします. ただ, 基本的にはalpのREADMEに書かれている通りなので, そちらを見る方が早いと思います! (或いは, 作者の方による紹介エントリを読むのもいいでしょう!)

インストール

9月27日現在の最新版であるv0.0.4のインストール方法は以下の通り.

$ wget https://github.com/tkuchiki/alp/releases/download/v0.0.4/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ sudo mv alp_linux_amd64 /usr/local/bin/alp
$ sudo chown root:root /usr/local/bin/alp

alp_linux_amd64.zipの部分は, 適宜alpを動かすマシンのアーキテクチャに応じて読み替えましょう. まあ, 大抵の場合はalp_linux_amd64.zipで良いと思います.

使い方

zipを展開すると得られるalp_{arch}コマンド(このままだと不便なので, alpにリネームしましょう!)に対し, -fオプションでアクセスログのパスを与えるとよいです.

$ alp -f /var/log/nginx/access.log
+-------+-------+-------+-------+-------+-----------+-----------+-----------+-----------+--------+------+
| COUNT |  MIN  |  MAX  |  SUM  |  AVG  | MAX(BODY) | MIN(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI  |
+-------+-------+-------+-------+-------+-----------+-----------+-----------+-----------+--------+------+
| 2     | 0.000 | 0.000 | 0.000 | 0.000 |   568.000 |   568.000 |  1136.000 |   568.000 | GET    | /123 |
| 1     | 0.000 | 0.000 | 0.000 | 0.000 |   568.000 |   568.000 |   568.000 |   568.000 | GET    | /    |
+-------+-------+-------+-------+-------+-----------+-----------+-----------+-----------+--------+------+

左から, 次のような意味になっています.

COUNT : そのURIにアクセスがあった回数
MIN : そのURIへのアクセスにかかった最小の時間
MAX : そのURIへのアクセスにかかった最大の時間
SUM : そのURIへの全アクセスにかかった時間の合計
AVG : そのURIへの全アクセスにかかった時間の平均
MIN(BODY) : そのURIが返した最小のレスポンスボディ(クライアントに転送したバイト数のうち, レスポンスヘッダのバイト数を引いたもの)のサイズ
MAX(BODY) : そのURIが返した最大のレスポンスボディのサイズ
SUM(BODY) : そのURIが返した全てのレスポンスボディの合計
AVG(BODY) : そのURIが返した全てのレスポンスボディの平均
METHOD : そのURIをどのメソッドで呼び出したか
URI : 計測対象となるURI

デフォルトでは, ~~AVG~~MAXでソートされ, 平均アクセス時間が長いMETHODとURIの組み合わせがより下に表示されるようになっています.

また, alpコマンドに対してオプションを与えることで, どのパラメータでソートするかを切り替えたり, クエリストリングを無視せずに解析したりすることも可能です.

Nginxとの連携

alpをNginxでつかう場合, Nginxのログフォーマットは$request_methodをmethodとして, $body_bytes_sizeをsizeとして, $upstream_response_time(Nginxが上位のサーバにリクエストを転送して, そのNginxがそのレスポンスを受け取るまでにかかった時間. つまり, アプリケーションが処理をするのにかかった時間)をapptimeとして, $request_uriをuriとして, LTSV形式で出力しなければなりません.

alpコマンドでは, --restime-labelや--apptime-labelなどのオプションを利用して, LTSVで出力したログのどのパラメータを利用するか指定出来る... ようなのですが, IUCON前にalpを試した時のv0.0.2では何故かうまく使えなかったので, 本番では以下のようなlog_formatを指定して, オプションで指定せずとも動作するようにしてから望みました:

    log_format ltsv "time:$time_local"
        "\thost:$remote_addr"
        "\tforwardedfor:$http_x_forwarded_for"
        "\treq:$request"
        "\tmethod:$request_method"
        "\turi:$request_uri"
        "\tstatus:$status"
        "\tsize:$body_bytes_sent"
        "\treferer:$http_referer"
        "\tua:$http_user_agent"
        "\treqtime:$request_time"
        "\truntime:$upstream_http_x_runtime"
        "\tapptime:$upstream_response_time"
        "\tcache:$upstream_http_x_cache"
        "\tvhost:$host"
    ;

~~現時点でv0.0.4ということは, この辺既に直っていそうな気がしますが,~~v0.0.4で, オプションによって, どのパラメータを利用するかを指定出来るようになったとのことですが, 一応Nginxのlog_formatの記載例ということで残しておきます.

まとめ

alpを使ったり, まあいろいろ(過去2年以上に!)準備をして臨んだのですが, 今年のISUCONもあまり芳しい成果を出すことが出来ませんでした... ただ, それで終わってしまうと良くないと思っていて, そこから得たものや学んだことをしっかりアウトプットして, 共有して, 翌日からの業務や次のISUCONに繋げていくのが大事だ! という話をチームメンバーとしていたので, alpについてまとめたテキストをブログに残しておくことにします.

ISUCON運営メンバーの皆様, 今年もありがとうございました!