読者です 読者をやめる 読者になる 読者になる

uzullaがブログ

uzullaがブログです。

ISUCONでベンチをするたびに、Slackに集計を張り付ける件

みなさんの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で本当にオフになってるか確認をわすれないように

今後の改善点

消し忘れ怖いので、nginxのログも再起動したらオフになる仕組みがほしいとおもった。環境変数つかえばできるかな(すくなくともApacheではできるのだが、nginxだとあんまりしらべてない、次回までにはやるかな)

Slackにポストされたでっかいテキストファイルは割と見づらい。なにせ集計結果は横幅がでかくなりがち。とはいえ外部のPasteBinに貼れば解決するかってそんな感じでもない(結局、ブラウザを開くので)。

「あるベンチ結果の集計結果をタブでみれるPastebin」みたいなのがあればいいかな〜っておもったけど、割と良い感じではない。

過去のベンチとの比較とかも考えられるけど、それは実際使わんやろ…と思って作らず。

昨今のISUCONではベンチマーカーがウェブで、スコアもブラウザにでるので終了検知が面倒(今回は手作業だった)。ローカルベンチだとなにもかんがえなくていいのだが。

alpの出力そのままだと、keywordの後につづく日本語の文字がパーセントエンコーディングになってて見づらい。ここはもう一段フィルタをいれて人がよめるようにすべき。(終わった今なら、それが重要だったと気付く)

SlackにはりつけるとどんどんSlackが荒れるので、Chをわけるか、GHのISSUEに専用のスレをたてるべきか、とおもっている。まあ…趣味かな。

プレインテキストは目が滑るので、出力された集計結果の注目すべき所の文字を赤くしたいなとおもった。

まとめ

まあ石器時代みたいな手法ですが、普段やっていること以外をやると事故るので…。

こういったタレは当日につくるのは無駄なので、是非とも事前の練習の時につくるべきですね。

しかしまぁ、私が言っても説得力ないよな!すまん!!!