MySQLを運用していて特定の時間帯だけ更新クエリが増えているのを見つけたときにバイナリログを探ったりすることはまぁまぁあると思います。最近はmysqlbinlogとperlのワンライナーをつかって調べています
mysqlbinlogをつかって特定の時間帯のログを調べるのは
$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941
こんな感じですね。ちなみにMySQL 4.0.x のmysqlbinlogにはstart-datetime、stop-datetimeのオプションがないので新しいバージョンが入っているサーバに転送するなりして実行しています。
この出力は
#120731 09:41:48 server id 9316 end_log_pos 798 Query thread_id=1743530 exec_time=0 error_code=0
SET TIMESTAMP=1343394948/*!*/;
UPDATE tbl
SET ....
WHERE id='10756480'
/*!*/;
# at 798
#120727 09:41:48 server id 9316 end_log_pos 825 Xid = 43790241
COMMIT/*!*/;
# at 825
#120731 09:41:48 server id 9316 end_log_pos 884 Query thread_id=1743530 exec_time=0 error_code=0
SET TIMESTAMP=1343394948/*!*/;
BEGIN
/*!*/;
# at 884
こんなフォーマットで得られます。このフォーマットだと目grepでどんなクエリが多いのか判断するのは難しいので、クエリ部分だけを抽出します。その際クエリ中の改行も消してしまいます
$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941 | perl -e 'while(<>){ chomp; next if m!^#!; if ( m{/\*!\*/;$} ) { $p .= $_; print "$p\n"; $p="" } else { $p .= $_." "} }'
すると
BEGIN /*!*/;
SET TIMESTAMP=1343394948/*!*/;
UPDATE tbl SET ... WHERE id='10756480' /*!*/;
COMMIT/*!*/;
こんな感じで1クエリ1行にまとまるので、目grepもしくは一つ前のエントリで紹介した「sort|uniq -c|sort -nr」などを使って集計すれば特徴的なクエリが見つけられるかもしれません。
さらに、どんなテーブルへのどの操作が多いのか調べるためにもうひとつワンライナーを組み合わせて
$ mysqlbinlog --start-datetime="2012-07-31 09:41:00" --stop-datetime="2012-07-31 09:45:00" mysql-bin.941 | perl -e 'while(<>){ chomp; next if m!^#!; if ( m{/\*!\*/;$} ) { $p .= $_; print "$p\n"; $p="" } else { $p .= $_." "} }'|perl -nle 'm!^(DELETE FROM|REPLACE INTO|INSERT INTO|UPDATE)\s+([^ ]+)!i && print "$1 $2"'
INSERT INTO tbl0
UPDATE tbl1
UPDATE tbl1
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
INSERT INTO tbl2
UPDATE tbl0
INSERT INTO tbl2
とすれば、操作と対象テーブルの組み合わせだけ抜き出せます。これも「sort|uniq -c|sort -nr」を使う事で
43 INSERT INTO tbl2
33 UPDATE tbl1
19 INSERT INTO tbl3
18 UPDATE tbl2
17 INSERT INTO tbl1
16 INSERT INTO tbl4
11 INSERT INTO tbl5
11 INSERT INTO tbl6
3 INSERT INTO tbl7
このように集計が可能になりました。
ここまでくれば、対象となる時間帯にだけある特徴的な操作を見つけられるので、ソースコードから該当箇所を探しだし何かしらの手立てを考える事ができます。ここ数週間のなかで実際にいくつか無駄な処理を発見してアプリケーションを修正できたりしています。
そういえば、mk-query-digestもbinlogが喰えるようなことがドキュメントに書いてあるのですが、うまく動かないっぽいのですが、どなたか使っている方いますか？
