ISUCONへの道~プロファイリングツール編~

こんばんは。
早速ISUCONに向けてプロファイリングツールを試して行きたいと思います。

# alpの導入
github.com

alp is Access Log Profile

alpとはAccess Log Profileの略なんですね。
とりあえず導入していきます。

// alpをダウンロード
$ wget https://github.com/tkuchiki/alp/releases/download/v0.0.4/alp_linux_amd64.zip
// zipを解凍するためにunzipをインストール
$ sudo apt install unzip
$ unzip alp_linux_amd64.zip
$ sudo mv alp /usr/local/bin/alp
$ sudo chown root:root /usr/local/bin/alp

これでalpの準備は万端です。

次にnginxの設定を修正指定いきます。

/etc/nginx/conf.d/log_format.confを新規に作り、下記を入力します。
下記では、access.logをalpが読み込めるフォーマットに整える設定です。

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

次に、これを読み込むためにnginx.confを修正します。
httpタグの中にincludeすることにより、log_format.confを展開してくれます。

http {
    ...
    include       /etc/nginx/conf.d/*.conf;
    ...
}

nginxを再起動します。

$ sudo nginx -s reload

これでnginxの設定も完了しました。

alpを実行してみます。

$ sudo alp -f /var/log/nginx/access.log

こんな感じで出力されます。
f:id:kazuki229_dev:20170928225053p:plain

# alpの使い方
これでalpを使ったログの解析ができましたが、これらのデータをどうみていけば良いか考えて行きましょう。
alpではアクセスされたエントリポイントごとに集計を行います。
したがって、列で表されているデータはエントリポイントごとの値となります。

名前 概要 備考
max 最長レスポンスの時間
min 最短レスポンスの時間
avg 全レスポンス時間の平均
sum 全レスポンス時間の合計
cnt アクセス数
uri URI
method メソッド
max-body 最大のボディサイズ
min-body 最少のボディサイズ
avg-body 平均のボディサイズ
sum-body 合計ボディサイズ
p1 1パーセンタイルのレスポンス時間 小さい方から1%目の時間
p50 50パーセンタイルのレスポンス時間 中央値
p99 99パーセンタイルのレスポンス時間 小さい方から99%目の時間
stddev レスポンス時間の標準偏差

となっています。

例として、max,sum,cntあたりを見てチューニングの当たりをつけてみましょう。

max
f:id:kazuki229_dev:20170929001114p:plain
sum
f:id:kazuki229_dev:20170929001210p:plain
count
f:id:kazuki229_dev:20170929001142p:plain

maxを見るに、/が最大7秒の時間がかかっており、/keyword/xxxといったアクセスに関しても4秒程度の時間がかかっていることがわかる。

sumを見ても、/が700秒と断トツにアクセスが来ているため、/を最適化すると効きそうな気がします。
ついで、POSTのエントリポイントである/login,/keyword,/starsが上位に並んでおり、これらも改善の余地があると思われます。

最後にcntを見ると、/starsが940回も来ているのがわかります。ただ、1アクセスあたりの時間がそこまでかかっていないので、改善してもあまり効果がないかもしれません。

これらを見る限り、とりあえずは/を最適化し、ついで/login, /keyword, /starsのPOST, /keyword/xxxのGETを最適化すれば良いかと思われます。


大会の時には、何回もベンチマークを回すため、ベンチマークを回す前にログをローテート、解析結果をslackに連携などできると良さそうです。


# 参考
papix.hatenablog.com