2008年11月10日月曜日

MySQLでバイナリログから更新系のクエリをトレースする

メモエントリ。
 
MySQLのバイナリログをSQLのトレース目的で使ったのでメモ。
 

MySQLのバイナリログ取得設定


MySQLのバイナリログをとっておけば色々出来る、その辺は公式やら書籍が詳しいので割愛。
 

取りあえず設定。
my.cnfを編集、[mysqld] のセクションに取りあえず3行入れよう、ディレクトリはmysqlユーザが読み書きできるところならどこでもいい、この例では yum でのデフォルトのdataディレクトリだ。
[mysqld]
・・・
log-bin=/var/lib/mysql/binary
expire_logs_days = 14
max_binlog_size=200M


"log-bin"だけでも良いけど、放っておくとどこまでもログが残る、1ファイル200MB制限・14日間保存と
ファイル容量を制限するのは、ログ抽出の際に不便だから。
 
 
これで MySQL を再起動すれば、"/var/lib/mysql/binary.index","/var/lib/mysql/binary.000001" ファイルが作成されている。
(※起動に失敗したらmy.cnfで指定しているエラーログを見ると大体分かる。)
 
バイナリログはこっち、 "/var/lib/mysql/binary.000001" ローテーションするごとに数字が増える。
 
 

バイナリログから更新系ログを抽出


バイナリログの設定が終わったので本題。
 

バイナリログには、データベースの基本機能、 CRUD のうちReadを除くCUDが記録されている。
これを mysqlbinlog コマンドでテキストデータ(=実行時のSQLクエリ)に戻せるのでやってみよう。
 

テスト用DBの作成と削除


とりあえずDBを作って消した。
#mysqladmin create test001 -p
#mysqladmin drop test001 -p

mysqladmin とかいう妙なコマンドを使ったが、実際どういうSQL文が実行されたのかこれではよく分からない。
が、実行結果がバイナリログに記録されているので安心。
 

変換したバイナリログを眺める


mysqlbinlog コマンドにバイナリログファイルを渡してみる、
# mysqlbinlog binary.000001

 

上記実行後、出力の一部が下記。
#081110 12:33:26 server id 1 end_log_pos 104655065 Query thread_id=1071 exec_time=0 error_code=0
SET TIMESTAMP=1226288006/*!*/;
SET @@session.foreign_key_checks=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
create database `test001`/*!*/;
# at 104655065
#081110 12:39:45 server id 1 end_log_pos 104655154 Query thread_id=1076 exec_time=0 error_code=0
SET TIMESTAMP=1226288385/*!*/;
drop database `test001`/*!*/;

 

ばっちり記録されている。
本来はフルバックアップからの差分とかでの利用が想定されているみたいだけど、WEBアプリ制作時のデバッグとか、わけのわからんアプリが何かしているので調査とか、そういう局面でも役に立つ。