みなさんのISUCONの参戦エントリを楽しく読みつつ、心にはダメージを負っているuzullaです、こんにちは。もう一週間くらい後に読もうかな。

さて、一昨日のISUCONでは繰り返しnginxのクエリやDBのクエリ解析結果をみていました。そこらへんを毎回手で叩くと大変だし、ファイルのシェアも面倒なので、解析したらそのままSlackにはりつけていました。その作業は半分くらい自動化されており、そのメモです。

使ったツール（一部）

alp
pt-query-digest
slackcat

github.com

alpについては皆さんご存じかもですが、LTSV形式のログをよしなに集計してくれるツールです。このツールで強いのは、/keyword/hogeと/keyword/ugoといった最近のバラけるURLを正規表現でまとめる事ができる事ですね。主にアクセス回数やアクセス平均時間などを確認するためにつかいました。

pt-query-digest

pt-query-digestはもはや説明不要というか、ググったほうがよいでしょうが、MysqlのSlow query logを集計してくれる君です。これは回数や、合計でかかった時間を特に重視していました。（ところでmysqldumpslowがここ最近バグってて集計がおかしいんですが直って欲しいですね）

github.com

slackcatは、指定したチャンネルにファイルをULしてくれる君です。とても便利。こういうツールは結構あるけどslackcatはシンプルでよかった。

これらを組み合わせることで、「計測開始」「ベンチ回す」「集計」「Slackにポスト」ができます。

なお、slackcatはデプロイ通知とかにも使えますので、その用途にもおすすめです。

どうやるか

素直にシェルスクリプトでいいんじゃないですかね。

#!/bin/bash
set -ex

# ログのリセット
:> /tmp/access.log
:> /tmp/mysql-slow.log

# slow query logの有効化
# my.cnfに書くと外すのを忘れるので、動的にONにしている
echo "set global slow_query_log_file = '/tmp/mysql-slow.log';set global long_query_time=0;set global slow_query_log = ON;" | mysql -u isucon -pisucon

# アプリの再起動
# slow_query_logを変更したらDB再接続が必要なので
sudo systemctl restart isuda.perl
sudo systemctl restart isutar.perl

ここでベンチをまわし、じっと待つ

終わったら以下を実行

#!/bin/bash
set -ex

# slow query をオフに
echo "set global slow_query_log = OFF;" | mysql -u isucon -pisucon

# アプリを再起動
sudo systemctl restart isuda.perl
sudo systemctl restart isutar.perl

# クエリ集計
export PT_DIGEST_FILENAME=/tmp/ptd-`date +%H%M%S`.txt

# ここでteeしてるのは、一応うごいたか目でみてたかったので
pt-query-digest --limit=100 --filter '$event->{bytes} <= 100000' /tmp/mysql-slow.log | tee $PT_DIGEST_FILENAME

cat $PT_DIGEST_FILENAME | /usr/local/bin/slackcat --channel 80percent --filename pt-digest.txt

# アクセスログ集計

export ALP_FILENAME=/tmp/alp-`date +%H%M%S`.txt
cat /tmp/access.log | /usr/local/bin/alp --aggregates="/keyword/.*","/stars.*","/\?.*" > $ALP_FILENAME
cat $ALP_FILENAME | /usr/local/bin/slackcat --channel 80percent --filename alp-result.txt

# 必要に応じて、他の集計もやったりする

後で集計をみかえしたくなるかもしれないので、一応毎回ファイル名は日時を振った。

まあこのように非常に原始的な手法なのだけれど、原始的がゆえにその場で修正しやすく、たとえばalpのaggregatesをへらしたパターンもつくったりできる。（今回だと、keywordのかたよりをみるために、一部のマッチを削ったりした）

pt-query-digestのフィルタはなかなか色々な機能があって、バカでかいクエリは（初期化とかでよくある）捨てるとか、マッチしたものだけをひっぱる、とかもできるのがよい（というかやらないとつらい）。limitは指定しないと集計除外されるクエリがでてくるので、全部出すように指定している。

（ところで、現実世界でmysqlコマンドの引数でパスワード指定とか正気ではないが、まあISUCONだからね！！！）

なお、UbuntuはAppArmorがあるので、デフォだとMysqlのスロークエリログを/tmp/に出力できない。別にここに出力される意味はないのだが、/tmpを使いたいならDisableしましょう。なお、Apparmorをaptで消すとmysqlごと消えるらしい、まじか。

# うろおぼえだが、こうやります。
$ sudo ln -s /etc/apparmor.d/usr.sbin.mysqld /etc/apparmor.d/disable/
$ sudo apparmor_parser -R /etc/apparmor.d/usr.sbin.mysqld
# 適当にググると大抵古い情報か嘘がみつかりますので、まあ公式ドキュメントをみましょう。
# https://help.ubuntu.com/lts/serverguide/apparmor.html
# aa-statusで本当にオフになってるか確認をわすれないように