GA

2024/12/16

MySQLのログと改行文字と個人の感想

この記事は MySQL Advent Calendar 2024 の16日目の記事です。
昨日の記事はまだ公開されていなさそうです。

TL;DR

  • MySQLのスローログ, ジェネラルログ, オプションによってはバイナリログも「実行されたクエリの改行文字まで全部記録する」
    • ゆえに改行文字を挟まずに投げてもらった方がgreppabilityが良くてうれしい
    • tail -f で見たい時以外は pt-query-digest を通せばどうにでもなる
  • 同じく「コメントも全て記録する」

TL;DRが全部言い切っちゃってますが、たとえばこんなSQLは

mysql80 19> INSERT INTO t1
    -> VALUES (100000001, 'one'),
    ->    (100000002, 'two');
Query OK, 2 rows affected (0.01 sec)
Records: 2  Duplicates: 0  Warnings: 0

こういう風に記録されます。

### スローログ
# Time: 2024-12-16T18:23:52.357891+09:00
# User@Host: root[root] @ localhost []  Id:    19
# Query_time: 0.013943  Lock_time: 0.000021 Rows_sent: 0  Rows_examined: 0 Thread_id: 19 Errno: 0 Killed: 0 Bytes_received: 70 Bytes_sent: 58 Read_first: 0 Read_last: 0 Read_key: 17 Read_next: 11 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2024-12-16T18:23:52.343948+09:00 End: 2024-12-16T18:23:52.357891+09:00
SET timestamp=1734341032;
INSERT INTO t1
VALUES (100000001, 'one'),
   (100000002, 'two');

### ジェネラルログ
2024-12-16T18:23:52.344212+09:00           19 Query     INSERT INTO t1
VALUES (100000001, 'one'),
   (100000002, 'two')

### バイナリログ
# at 529
#241216 18:23:52 server id 1080  end_log_pos 529 CRC32 0x898f1fcf       Rows_query
# INSERT INTO t1
# VALUES (100000001, 'one'),
#    (100000002, 'two')
# at 529
#241216 18:23:52 server id 1080  end_log_pos 529 CRC32 0x5aec8a28       Table_map: `d1`.`t1` mapped to number 99
# has_generated_invisible_primary_key=0
# at 529
#241216 18:23:52 server id 1080  end_log_pos 529 CRC32 0xaf62b85b       Write_rows: table id 99 flags: STMT_END_F

BINLOG '
qPFfZx04BAAAVwAAAAAAAACAAD9JTlNFUlQgSU5UTyB0MQpWQUxVRVMgKDEwMDAwMDAwMSwgJ29u
ZScpLAogICAoMTAwMDAwMDAyLCAndHdvJynPH4+J
qPFfZxM4BAAANgAAAAAAAAAAAGMAAAAAAAEAAmQxAAJ0MQACCA8CgAACAQGAAgP8/wAoiuxa
qPFfZx44BAAAPQAAAAAAAAAAAGMAAAAAAAEAAgAC/wAB4fUFAAAAAANvbmUAAuH1BQAAAAADdHdv
W7hirw==
'/*!*/;
### INSERT INTO `d1`.`t1`
### SET
###   @1=100000001 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='one' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
### INSERT INTO `d1`.`t1`
### SET
###   @1=100000002 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='two' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */

バイナリログは binlog_format がSTATEMENTの場合はもちろん改行込みで記録される。ROWの場合は実データ部分( Write_rows イベント) は影響を受けないけれど、 binlog_rows_query_events=ON で追加出力される Rows_query イベント (↑の出力の1つ目。2つ目のイベントは Write_rows ) は影響を受ける。

で、これが1行にまとまるとgreppabilityが上がって嬉しいという話です。主には tail -f で効きます。

$ tail -f general_log_or_slow_log | grep -i 'SELECT' | grep -i 'table_which_I_need_to_watch'
### SELECTとFROMが別の行にあるとgrepできない！

別に grep -B 2 とかで引けるといえば引けるんですが、そうするとSELECT, UPDATE, INSERT, DELETEを分けるのが若干面倒。
なお、 tail -f じゃなくていい/binlog以外なら単に pt-query-digest に食わせればいいだけです。

コードの中でSQLを書くときに改行コードを入れないと長いSQLは当然読みにくくなるので、クエリを実行する側で吸収すると便利なはず。

https://github.com/yoku0825/ytkit/blob/bd23f9c8ed0768829c597983bed5a223a677bdd2/lib/Ytkit/MySQLServer.pm#L521-L527

ついでに呼び出し元関数をコメントで添えるようにしておくといろいろ捗りました（ ytkit の文字列と呼び出し元関数を両方入れておくことで、 grep -v ytkit だけで全部を除外できたりデバッグの時にジェネラルログから関数ごとに当たれたり)

この「呼び出し元関数をコメントで添える」アイディアは kazeburoさんのDBIx::Sunny を真似しました。
（いつぞやのISUCONでPerl参考実装にこれが使われていて感動したのが最初でした）

他、記憶は曖昧ですが DBeaver? とか Redashもコメントで呼び出した人(?) の情報を足してくれた気がします。
アプリケーションコードにコメントが埋め込まれていると、「今出てるスローログってどんなのです？」「xxxxx ってコメントがついたクエリなんですけど…」とかコミュニケーションが捗ります。

観測範囲でやってる人が大多数でないということはなんか難しいということなのかも知れませんが、やっておくといつか誰かを助けるかもしれないTIPSでした。

明日は wtnbnさん です！

​
投稿者 時刻:
ラベル:

0 件のコメント :

コメントを投稿

登録: コメントの投稿 ( Atom )