ちゃんるいすのブログ

オタクエンジニアの雑記

GTID で errant transaction に悩んだら


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 回出現する理由

気になる。

1回目

# 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=
'/*!*/;

起動時。 これが何をしているのかは不明なので教えてください。

2回目

# 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 に保存される。

3回目

# 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

f:id:rarirureluis:20200217152638p:plain

after

f:id:rarirureluis:20200217152649p:plain

ac8a2a1b-31d2-11ea-ad13-fa163eee324c:1-14ac8a2a1b-31d2-11ea-ad13-fa163eee324c:1-15 になった。無事、errant transaction の完成です。

解決

flush slow logs をやめるのは流石にキツイのでスクリプトを回す。

Orchestrator を Mackerel と組み合わせて幸せを掴むスクリプト - ちゃんるいすのブログ

はてなシンタックスハイライトって、shell とか bash とか無いんだ、、、(今更)