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が喰えるようなことがドキュメントに書いてあるのですが、うまく動かないっぽいのですが、どなたか使っている方いますか?

このブログ記事について

このページは、Masahiro Naganoが2012年8月 2日 18:34に書いたブログ記事です。

ひとつ前のブログ記事は「sort と uniq でさくっとランキングを出力する」です。

次のブログ記事は「mod_copy_header ってのを書いた話 Re: Apache上のPerl FastCGIはCustomLogにデータを書くことができるか?」です。

最近のコンテンツはインデックスページで見られます。過去に書かれたものはアーカイブのページで見られます。

ウェブページ

OpenID対応しています OpenIDについて
Powered by Movable Type 4.27-ja