仕事でしょっちゅうmysqlのバイナリログを掘っているのですが、mysqlbinlogが使いづらくて困っていました。なんせmysqlのバイナリログは、以下の問題があります。
・すぐサイズが大きくなるため、1つのDBのログを追うために、相当時間がかかる。
・mysqlbinlogコマンドから出るデータは、１行になっていないため、grepとかしづらい。
・バイナリデータ突っ込んだりしている場合は、文字化けて、続きが読めなくなったりする。
・mysqlbinlogコマンドも、1Gクラスのログだと、とにかく遅い。
・ログを追ったり調査するだけの人間からすると、無意味なログが多すぎる。
apacheのログみたいに、1行１リクエストになっていれば、grepですぐに引けるのですが、目的のクエリ探すのが、しんどい、しんどい。
また、うちは１システムで、１日1GBクラスのログがたまるため(バイナリアップロード分はほとんど入っていないにもかかわらず・・)ログローテートサイズを1Gにしているのですが、このログをmysqlbinlogコマンドで掘るのに時間がかかりすぎて・・
ついに、やってられなくなったため、木曜から２日かけて（やっつけですが）、以下の仕様で、バイナリログを閲覧するコマンドアプリを作ってみました。
・高速化のため、バイナリログを直接読み込む
・ログはgrepとか行いやすいように、「１行１クエリ」にする。（クエリ内改行は、スペース置換）
・クエリは、utf8mb4文字列以外であれば「?」に置換して、化けないようにする。
・DB(スキーマ)ごとにログをフォルダに振り分けて保存してくれる。
・時間フィルタとかも使いたい。
* 名付けて、mysqlbinlogexです。（パクリくさい名前ですね）
ソースはここ(github)に置いてあります。同じような悩みを抱えている方、一緒にブラッシュアップしていきませんか？(行ベースロギングには現時点(2014/05/24)では対応していません・・。)
なお、mysqlのバイナリログのフォーマットが、探しかたが悪いのか、どこを探しても断片的にしか無く、結局mysqlのソース追う羽目になったため、以下に調査内容をまとめておきます。
* mysqlのバイナリログフォーマットについて
1. 全体のおおまかなフォーマット
・ はじめの4byteは、必ず「0xfe 0×62 0×69 0x6e」。これがmysqlのバイナリログの証です。
・ その後は、次の形式のがループして最後まで続きます。
| ログヘッダ(19Byte) | クエリとクエリステータス(可変) |
・ つまり、binlogファイルの中身は、以下のような感じです。
0xfe 0x62 0x69 0x6e | ログヘッダ(19Byte) | クエリとクエリステータス(可変) | | ログヘッダ(19Byte) | クエリとクエリステータス(可変) | | ログヘッダ(19Byte) | クエリとクエリステータス(可変) | | ログヘッダ(19Byte) | クエリとクエリステータス(可変) | ・・・・・
2. 各クエリセグメントのフォーマット
・ 各クエリセグメントは、上記のように、以下の形式です。
| ログヘッダ(19Byte) | クエリとクエリステータス(可変) |
・ 19byteのログヘッダは、下記の内容を含んでいます。なお、すべてリトルエンディアンです。ここ(本家)が詳しいです。
| ts(4byte) | type(1byte) | masterID(4byte) | size(4byte) | master_pos(4byte) | flags(2byte) |
– ts(4byte)：クエリ動作日時。unix_timestamp。
– type(1byte)：0x0f(バイナリログ開始)、0×02(通常のステートメントログ)、0×17-0×19(rowベースステートメント)とか。重要
– masterID(4byte)：読んで字の如く。自分の場合は、自分のID。
– size(4byte)：このセグメントのバイト長。ログヘッダの19byteを含む。超重要
– master_pos：読んで字の如く。
– flags：普通のログは、0×00。その他は本家(上にリンクあり)参照。
・ 19byteのデータを読んだら、「クエリとクエリステータス」の長さが決まります。「クエリとクエリステータス」は以下のフォーマットです。
| クエリヘッダ(13byte) | ステータスデータ(可変) | データベース名称(可変) | 0x00 | クエリ(可変) |
・ クエリヘッダは以下のフォーマットです。
| thread_id(4byte) | exec_time_sec(4byte) | error_code(2byte) | status_size(2byte) |
– thread_id(4byte)：クエリ実行者のスレッドID。同じであれば、同じコネクションで動作したことがわかる。
– exec_time_sec(1byte)：クエリ実行時間
– error_code(2byte)：エラーコードらしい。内容はあまりよくわからない。
– size(4byte)：続きの「ステータスデータ」のバイト数。超重要
・ ここまで来て、やっと最も大事なDB名称とクエリの位置がわかります。データベース名称は0×00が入っているわけないので、ステータスデータが終わったところから、初めて0×00が来たところまでが、DB名です。空の場合もあります。(useしないで動作させると空になるようです。sequel proとか、navicatとかで操作した場合とか。)残りがクエリです。ただし、mysql5.6.1以降のバージョンが吐き出したバイナリログの場合、クエリ部の最後に、crc32チェックサムが付いています。このため、mysql5.6.1以上の場合は、終わり4byteを削ってあげる必要性があります。
・ クエリセグメントについて全部記載すると、以下のようになります。こいつが何度も繰り返されているイメージです。
| ts(4byte) | type(1byte) | masterID(4byte) | size(4byte) | master_pos(4byte) | flags(2byte) | | thread_id(4byte) | exec_time_sec(4byte) | error_code(2byte) | status_size(2byte) | | ステータスデータ(可変) | データベース名称(可変) | 0x00 | クエリ(可変) |
久しぶりに投稿しました。次は、いつになるだろ。予定は、「mysqlレプリケーションで、マスタが落ちた場合にスレーブを落とさなければならないときの注意事項」を書きたいと思います。(5.6.17で4台レプリ組んで、検証していたときにはまりました。)
全然関係ないですが、弊社では、現在、開発チームメンバを大々募集中です。このブログをこの位置まで読んでいただいた方、ぜひ応募してみてください。給与アップも(きっと)間違いなし(かも・・)。一緒にwebシステムのジェネラリストになりませんか？
- Older: 最近ご無沙汰していました。