TL;DR
- flush slow logs のタイミングでバイナリログに書き込まれる
- それによって GTID がズレる ＝ errant transaction
- このスクリプトを mackerel-agent で定期実行することで解決
事象
あるタイミングでスレーブの GTID が進んで errant gtid が起きる。
flush slow logs はバイナリログに書かれるよ
FLUSH PRIVILEGESやFLUSH TABLESはバイナリーログに書かれるのでgtid_executedに記録されるよ
バイナリログを調べる
general_log に書かれる server id はもちろんスレーブの。
バイナリログのは server id は、マスターの server id になる。
↓ こんなスクリプトで調べていった。
#!/bin/bash logs=(000003 000004 000005 000006 000007 000008 000009 000010 000011 000012 000013 000014 000015) for log in "${logs[@]}" do mysqlbinlog /var/lib/mysql/mysql-bin.${log} --result-file=/mnt/data/output_${log} -v echo "${log}: $( cat /mnt/data/output_${log} | grep 'server id 101941095' |wc -l )" done
これの出力結果はこんな感じになる ↓
000003: 3
000004: 3
000005: 3
000006: 3
000007: 3
000008: 3
000009: 3
000010: 5
000011: 3
000012: 3
000013: 3
000014: 3
000015: 3
server_id: 101941095 がバイナリログ上に出現した数が出力される。
3 は正常で、それ以上が怪しいやつ。
つまり、mysql-bin.000010 が怪しい。
mysql-bin.000010 を調べる
# at 418792896 #200216 3:12:01 server id 101941095 end_log_pos 418792944 CRC32 0xe049bbeb GTID [commit=yes] SET @@SESSION.GTID_NEXT= 'ac8a2a1b-31d2-11ea-ad13-fa163eee324c:11'/*!*/; # at 418792944 #200216 3:12:01 server id 101941095 end_log_pos 418793022 CRC32 0x1b3c4ada Query thread_id=3743 exec_time=0 error_code=0 SET TIMESTAMP=1581790321/*!*/; SET @@session.sql_mode=1075838976/*!*/; flush slow logs /*!*/; # at 418793022 # #200216 3:12:01 server id 101941095 end_log_pos 418793022 CRC32 0x1b3c4ada Query thread_id=3743 exec_time=0 error_code=0 # SET TIMESTAMP=1581790321/*!*/; # SET @@session.sql_mode=1075838976/*!*/; # flush slow logs # /*!*/; # # at 418793022 # // SET TIMESTAMP=1581803224/*!*/; BEGIN /*!*/;
flush slow logs … :thinking_face:
（寄り道）3 回出現する理由
気になる。
１回目
# at 4
#200215 14:22:31 server id 101941095 end_log_pos 120 CRC32 0x64963fc6 Start: binlog v 4, server v 5.6.44-log created 200215 14:22:31
BINLOG '
F4BHXg9nfxMGdAAAAHgAAAAAAAQANS42LjQ0LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAcY/
lmQ=
'/*!*/;
起動時。
これが何をしているのかは不明なので教えてください。
２回目
# at 121
#200215 14:22:31 server id 101941095 end_log_pos 471 CRC32 0x725344f8 Previous-GTIDs
# 54a349d8-311a-11ea-a861-fa163efc07d0:1-10,
# 7aab7d0a-32f1-11ea-b461-fa163e7976a1:1-10,
# 7ac09f23-32f1-11ea-b461-fa163ed61f9a:1-502880417,
# 864f8199-0b58-11ea-b22c-fa163eb7e9f7:1-892916580,
# ac8a2a1b-31d2-11ea-ad13-fa163eee324c:1-10,
# d46dd772-0b58-11ea-b22e-fa163ee8afa4:1-10,
# d7128fda-0b58-11ea-b22e-fa163e9f03bc:1-1778530447,
# fef8730c-45b7-11ea-aed0-fa163e09984a:1-10
GTID の仕様上で、過去に実行してきた GTID を全て知っている必要がある。
バイナリログの先頭には、↑ のように今まで実行した GTID を記録し、gtid_executed に保存される。
３回目
# at 1073741881
#200215 16:29:17 server id 101941095 end_log_pos 1073741928 CRC32 0xdecb3708 Rotate to mysql-bin.000003 pos: 4
DELIMITER ;
# End of log file
新しいバイナリログへのローテート時
原因
まさにこれだった。
FLUSH PRIVILEGESやFLUSH TABLESはバイナリーログに書かれるのでgtid_executedに記録されるよ
確認
flush slow logs を叩いてみる。
before
after
ac8a2a1b-31d2-11ea-ad13-fa163eee324c:1-14 → ac8a2a1b-31d2-11ea-ad13-fa163eee324c:1-15 になった。無事、errant transaction の完成です。
解決
flush slow logs をやめるのは流石にキツイのでスクリプトを回す。