MySQLがbinlogファイルを手動で登録し、マスタースレーブ異常を引き起こす理由

1. 問題の原因

友人の @水米田から、POSITION に基づくマスタースレーブについて質問がありました。彼は次のことをした

バックアップされたbinlogファイルをディレクトリに追加し、インデックスファイルを変更して、これらのbinlogファイルを追加します。
バイナリログをフラッシュする
すると、マスタースレーブ環境全体が大幅に遅延します。

2. 友達のテスト

これは私の友人 @徐晨亮による別のテストです:

マスター側:
(root:db1@xucl:10:30:22)[(なし)]> バイナリログを表示します。
+---------------------+------------+
| ログ名 | ファイルサイズ |
+---------------------+------------+
|mysql-binlog.000031 | 1019 |
|mysql-binlog.000032 | 424 |
|mysql-binlog.000033 | 244 |
|mysql-binlog.000034 | 2332 |
|mysql-binlog.000035 | 2134 |
|mysql-binlog.000036 | 845915 |
|mysql-binlog.000037 | 11735 |
|mysql-binlog.000038 | 284 |
|mysql-binlog.000039 | 284 |
|mysql-binlog.000040 | 284 |
|mysql-binlog.000041 | 284 |
|mysql-binlog.000042 | 234 |
+---------------------+------------+
セット内の行数は 12 です (0.00 秒)
(root:db1@xucl:10:30:34)[(なし)]> バイナリログを 'mysql-binlog.000039' に消去します。
クエリは正常、影響を受けた行は 0 行 (0.00 秒)
(root:db1@xucl:10:30:49)[(なし)]> バイナリログを表示します。
+---------------------+-----------+
| ログ名 | ファイルサイズ |
+---------------------+-----------+
|mysql-binlog.000039 | 284 |
|mysql-binlog.000040 | 284 |
|mysql-binlog.000041 | 284 |
|mysql-binlog.000042 | 234 |
+---------------------+------------+
セット内の 4 行 (0.00 秒)
挿入データ (root:db1@xucl:10:31:23) を実行します [xucl]> insert into t values(9,9);
バックアップしたbinlogを元のディレクトリにコピーし、インデックスファイルを変更して[root@izbp12nspj47ypto9t6vyez logs]# llを登録します。
総使用量 884
-rw-r----- 1 mysql mysql 1019 5月20日 22:03 mysql-binlog.000031
-rw-r----- 1 mysql mysql 424 5月20日 22:03 mysql-binlog.000032
-rw-r----- 1 mysql mysql 244 5月20日 22:03 mysql-binlog.000033
-rw-r----- 1 mysql mysql 2332 5月20日 22:03 mysql-binlog.000034
-rw-r----- 1 mysql mysql 2134 5月20日 22:03 mysql-binlog.000035
-rw-r----- 1 mysql mysql 845915 5月20日 22:03 mysql-binlog.000036
-rw-r----- 1 mysql mysql 11735 5月20日 22:05 mysql-binlog.000037
-rw-r----- 1 mysql mysql 284 5月20日 22:06 mysql-binlog.000038
-rw-r----- 1 mysql mysql 284 5月21日 10:28 mysql-binlog.000039
-rw-r----- 1 mysql mysql 284 5月21日 10:28 mysql-binlog.000040
-rw-r----- 1 mysql mysql 284 5月21日 10:28 mysql-binlog.000041
-rw-r----- 1 mysql mysql 491 5月21日 10:31 mysql-binlog.000042
-rw-r----- 1 mysql mysql 204 5月21日 10:30 mysql-binlog.index
メインライブラリのバイナリログのフラッシュ
(root:db1@xucl:10:32:51)[(なし)]> バイナリログをフラッシュします。
クエリは正常、影響を受けた行は 0 行 (0.01 秒)
(root:db1@xucl:10:32:57)[(なし)]> バイナリログを表示します。
+---------------------+-----------+
| ログ名 | ファイルサイズ |
+---------------------+-----------+
|mysql-binlog.000031 | 1019 |
|mysql-binlog.000032 | 424 |
|mysql-binlog.000033 | 244 |
|mysql-binlog.000034 | 2332 |
|mysql-binlog.000035 | 2134 |
|mysql-binlog.000036 | 845915 |
|mysql-binlog.000037 | 11735 |
|mysql-binlog.000038 | 284 |
|mysql-binlog.000039 | 284 |
|mysql-binlog.000040 | 284 |
|mysql-binlog.000041 | 284 |
|mysql-binlog.000042 | 541 |
|mysql-binlog.000043 | 234 |
+---------------------+------------+
セット内の行数は 13 です (0.00 秒)
この時点で、スレーブは次のエラーを報告します。
(root:db1@xucl:10:31:05)[(なし)]> スレーブステータスを表示\G
************************** 1. 行 ****************************
        スレーブ_IO_状態:
         マスターホスト: 127.0.0.1
         マスターユーザー: repl
         マスターポート: 3306
        接続再試行: 60
       マスターログファイル: mysql-binlog.000035
     読み取りマスターログ位置: 194
        リレー ログ ファイル: izbp12nspj47ypto9t6vyez-relay-bin.000011
        リレーログ位置: 373
    リレーマスターログファイル: mysql-binlog.000035
       スレーブIO実行中: いいえ
      スレーブSQL実行中: はい
       レプリケート_Do_DB:
     レプリケート_無視_DB:
      テーブルの複製:
    無視テーブルを複製:
   Replicate_Wild_Do_Table:
 Replicate_Wild_Ignore_Table:
          最終エラー番号: 0
          最終エラー:
         スキップカウンタ: 0
     実行マスターログポジション: 194
       リレーログスペース: 648
       Until_Condition: なし
        ログファイルまで:
        ログ位置まで: 0
      マスターSSL許可: いいえ
      マスターSSLCAファイル:
      マスターSSLCAパス:
       マスターSSL証明書:
      マスターSSL暗号:
        マスターSSLキー:
    マスターより遅れている秒数: NULL
Master_SSL_Verify_Server_Cert: いいえ
        最終IOエラー番号: 1236
        Last_IO_Error: バイナリ ログからデータを読み取るときに、マスターから致命的なエラー 1236 が発生しました: '@@GLOBAL.GTID_MODE = OFF の場合、GTID トランザクションを複製できません。ファイル /storage/single/mysql3306/logs/mysql-binlog.000035、位置 194。最初のイベント 'mysql-binlog.000039' は 234 にあり、最後のイベントは '/storage/single/mysql3306/logs/mysql-binlog.000035' から 259 に読み取られ、最後のバイトは '/storage/single/mysql33' から読み取られました。
        最終SQLエラー番号: 0
        最後のSQLエラー:
 Replicate_Ignore_Server_Ids:
       マスターサーバー ID: 3306
         マスター_UUID: e8bdf01a-c79b-11e8-82b3-00163e088352
       マスター情報ファイル: mysql.slave_master_info
          SQL_遅延: 0
     SQL_残り遅延: NULL
   Slave_SQL_Running_State: スレーブはすべてのリレーログを読み取りました。さらに更新を待機しています。
      マスター再試行回数: 86400
         マスターバインド:
   最終IOエラータイムスタンプ: 190521 10:32:57
   最終SQLエラータイムスタンプ:
        マスターSSL証明書:
      マスターSSLCrlパス:
      取得済み_Gtid_Set:
      実行されたGtidセット: 4c423515-6661-11e9-b767-00163e088352:1-7、
e8bdf01a-c79b-11e8-82b3-00163e088352:1-57192
        自動位置: 0
     Replicate_Rewrite_DB:
         チャンネル名:
      マスター TLS バージョン:
セット内の 1 行 (0.00 秒)
スレーブ側のエラーから判断すると、マスターがバイナリログをフラッシュした後、スレーブ側が登録されたバイナリログを読み取って再度適用しているようです。

3. 現象の説明

テスト全体から判断すると、MySQL は手動で登録したファイルを転送して適用しているようです。このエラーは、ライブラリが以前は GITD_MODE=ON であったが、テスト中に GTID_MODE がオフになり、POSITION モードに変更されたために発生します。このエラーは、DUMP スレッドが以下を検出するために発生します。

この絵は私が書いた新しいシリーズからのものです（まだ出版されていませんが、おそらく年末までに完成する予定です）。いずれにせよ、DUMP スレッドは古い binlog ファイルの転送を開始しました。それで、その理由は何でしょうか?以下で説明させていただきます。

4. binlog でのバイナリログのフラッシュ操作

バイナリログのフラッシュには次の操作が含まれます。

新しいbinlogファイル名を取得する
古いバイナリログを閉じる
インデックスファイルを閉じる
インデックスファイルを開く
新しいバイナリログを開く
インデックスファイルに新しいバイナリログを追加する

詳細については、関数 MYSQL_BIN_LOG::new_file_impl を参照してください。新しい binlog ファイル名の取得は、次のコードを含む find_uniq_filename 関数を通じて実装されることに注意してください。

 file_info = dir_info->dir_entry;
 (i = dir_info->number_off_files; i--; file_info++) の場合
 {
  if (strncmp(file_info->name, start, length) == 0 &&
  is_number(file_info->name+length, &number,0))
  {
   set_if_bigger(max_found, 数値);
  }
 }
...
 *next = (need_next || max_found == 0) ? max_found + 1 : max_found;

一般的な意味は、インデックスファイル内の binlog ファイルをスキャンし、シーケンス番号が最も高いファイルを取得して、1 を追加することです。スタックフレームは次のとおりです。

#0 find_uniq_filename (name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog"、next=0x7fffec5ec678、need_next=true)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3679 で
#1 0x000000000187d208 が generate_new_log_name にあります (new_name=0x7fffec5ec6d0 "/mysqldata/mysql3340/log/binlog"、new_ext=0x0、 
  log_name=0x7ffedc011520 "/mysqldata/mysql3340/log/binlog"、is_binlog=true) /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3767 にあります
#2 MYSQL_BIN_LOG::new_file_impl の 0x0000000001884fdb (this=0x2e83640、need_lock_log=false、extra_description_event=0x0)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7175 で
#3 MYSQL_BIN_LOG::new_file_without_locking の 0x0000000001884cbb (this=0x2e83640、extra_description_event=0x0)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7099 で
#4 MYSQL_BIN_LOG::rotate の 0x0000000001886b6b (this=0x2e83640、force_rotate=true、check_purge=0x7fffec5ecbfb)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7775 で
#5 MYSQL_BIN_LOG::rotate_and_purge の 0x0000000001886d53 (this=0x2e83640、thd=0x7ffedc000b90、force_rotate=true)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:7846 で

したがって、インデックスファイルを手動で変更した場合でも、実際にはインデックスファイルをスキャンするため、バイナリログのフラッシュに問題はありません。
同時に、flush binary logs によってインデックスファイルが再ロードされることがわかります。この時点で、手動で変更されたインデックスファイルが有効になります。show binary logs を使用して、追加したファイルを表示します。

5. 主人と奴隷の問題の出現

binlog が切り替えられた後、DUMP スレッドは次の binlog ファイルも読み取る必要があります。どのファイルを読み取るかをどのように決定するかを見てみましょう。

各 binlog ファイルをループするコードは、関数 sender.run() にあります。次の文は次の binlog ファイルを見つけるためのものです。

int エラー = mysql_bin_log.find_next_log(&m_linfo, 0);

mysql_bin_log.find_next_log には次のコードが含まれています。

 my_b_seek(&index_file, linfo->index_file_offset);//オフセット linfo->index_file_start_offset = linfo->index_file_offset;
 length=my_b_gets(&index_file, fname, FN_REFLEN)); //ファイル名を読み取ります...
  if (normalize_binlog_name (full_fname, fname, is_relay_log))
...

 linfo->index_file_offset = my_b_tell(&index_file); // 次回の使用に備えてオフセットが新たに記録されます

DUMP スレッドは実際にはインデックスファイル全体をスキャンするのではなく、インデックスファイルのオフセットを読み取ることがわかります。インデックスファイルを手動で変更すると、オフセットが台無しになります。したがって、DUMP によって送信される次のファイルは未定義になります。そのため、手動で登録したbinlogファイルをスレーブライブラリに送信する現象が発生します。この場合、次のような状況が発生する可能性があります。

GTID_MODE がオフで POSITION が使用されている場合、重複行などのエラーが報告されます。
GTID_MODE および AUTO_POSITION=1 の場合、DUMP スレッドは GTID をフィルタリングして送信しません。イベントが送信されないため、遅延は一定期間 0 のままになります。
GTID_MODE および AUTO_POSITION=0 の場合、GITD_EVENT を適用するときに SQL スレッドがフィルタリングされ、遅延が非常に大きくなる可能性があります。

GTID はこの問題を回避できるかもしれませんが、DUMP スレッドはすでに古い binlog ファイルを送信することを検討しており、これは不適切です。

6. バイナリログをパージするとこのオフセットを維持できる

バイナリログを消去しても問題が発生しないのはなぜでしょうか? バイナリログを消去するステートメントでは、オフセットが次のように維持されるためです。

 仮想void演算子()(THD *thd)
 {
  LOG_INFO* ログ情報;
  mysql_mutex_lock(&thd->LOCK_thd_data);
  if ((linfo = thd->current_linfo)) //b binlog.cc:2829
  {
   /*
    インデックスファイルのオフセットは、次の場合にのみパージオフセットより小さくなります。
    インデックスファイルの読み取りを開始しました。
    調整するものは何もありません。
   */
   (linfo->index_file_offset < m_purge_offset) の場合
    linfo->致命的 = (linfo->index_file_offset != 0);
   それ以外
    linfo->index_file_offset -= m_purge_offset;
  }
  mysql_mutex_unlock(&thd->LOCK_thd_data);

linfo->index_file_offset -= m_purge_offset; のようなステートメントが表示されます。スタックフレームは次のとおりです。

#0 Adjust_offset::operator() (this=0x7fffec5ec720, thd=0x7ffedc000be0) /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2831 で
#1 0x0000000000eef320、Do_THD::operator() (this=0x7fffec5ec6a0、thd=0x7ffedc000be0)、/mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:46
#2 std::for_each<THD**, Do_THD> 内の 0x0000000000eefa0f (__first=0x3003358、__last=0x3003368、__f=...)
  /usr/lib/gcc/x86_64-redhat-linux/4.4.7/../../../../include/c++/4.4.7/bits/stl_algo.h:4200 にあります
#3 Global_THD_manager::do_for_all_thd の 0x0000000000eeefc0 (this=0x3003340、func=0x7fffec5ec720)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/mysqld_thd_manager.cc:273 で
#4 0x000000000187ae0a が、adjust_linfo_offsets (purge_offset=0) にあります (/mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:2873)
#5 MYSQL_BIN_LOG::remove_logs_from_index の 0x0000000001883239 (this=0x2e83640、log_info=0x7fffec5ec7d0、need_update_threads=true)
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6352 で
#6 0x0000000001883676 in MYSQL_BIN_LOG::purge_logs (this=0x2e83640、to_log=0x7fffec5eca80 "/mysqldata/mysql3340/log/binlog.000001"、included=false、 
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:6469 で、need_lock_index=true、need_update_threads=true、decrese_log_space=0x0、auto_purge=false が見つかりました
#7 purge_master_logs 内の 0x000000000187b4b5 (thd=0x7ffee0000c00、to_log=0x7ffee0006600 "binlog.000001")
  /mysqldata/percona-server-locks-detail-5.7.22/sql/binlog.cc:3127 で

7. POSITIONモードでエラーをテストする

1. 環境

mysql> バイナリログを表示します。
+---------------+-----------+
| ログ名 | ファイルサイズ |
+---------------+-----------+
| binlog.000001 | 198 |
| バイナリログ.000002 | 154 |
+---------------+-----------+
セット内の 2 行 (0.00 秒)

mysql> show テーブル testcp \G;
************************** 1. 行 ****************************
    テーブル: testcp
テーブルの作成: CREATE TABLE `testcp` (
 `id` int(11) NULLではない、
 主キー (`id`)
) エンジン=InnoDB デフォルト文字セット=utf8
セット内の 1 行 (0.00 秒)

エラー： 
クエリが指定されていません

2. ステートメントを実行する

メインライブラリ:

mysql> testcp に値を挿入します(20);
クエリは正常、1 行が影響を受けました (0.43 秒)

mysql> testcp から * を選択します。
+----+
|id|
+----+
| 10 |
| 20 |
+----+
セットに2行（0.01秒）

ライブラリから:

mysql> スレーブステータスを表示します \G;
************************** 1. 行 ****************************
        Slave_IO_State: マスターがイベントを送信するのを待機中
         マスターホスト: 192.168.99.41
         マスターユーザー: repl
         マスターポート: 3340
        接続再試行: 60
       マスターログファイル: binlog.000002
     読み取りマスターログ位置: 417
        リレーログファイル: relay.000004
        リレーログ位置: 624
    リレーマスターログファイル: binlog.000002
       スレーブIO実行中: はい
      スレーブSQL実行中: はい
...
mysql> testcp から * を選択します。
+----+
|id|
+----+
| 10 |
| 20 |
+----+

このとき、DUMP スレッドインデックスファイルのオフセットポインターは次のようになります。

3. メインデータベースはバイナリログのパージを実行します。

これを実行する前に、元の binlog.000001 を binlog.000001bak にコピーします。後でコピーし直す必要があるためです。

mysql> バイナリログを 'binlog.000002' に消去します。
クエリは正常、影響を受けた行は 0 行 (3.14 秒)

mysql> バイナリログを表示します。
+---------------+-----------+
| ログ名 | ファイルサイズ |
+---------------+-----------+
| binlog.000002 | 417 |
+---------------+-----------+
セット内の 1 行 (0.00 秒)

バイナリログの消去コマンドはオフセットポインターを維持するため、DUMP スレッドのインデックスファイルオフセットポインターは次のようになります。

4. 手動変更

binlog.000001bak を binlog.000001 にコピーし、インデックスファイルを変更して binlog.000001 を追加し直し、次のようにバイナリログをフラッシュします。

mysql> バイナリログをフラッシュします。
クエリは正常、影響を受けた行は 0 行 (0.15 秒)

mysql> バイナリログを表示します。
+---------------+-----------+
| ログ名 | ファイルサイズ |
+---------------+-----------+
| binlog.000001 | 198 |
| binlog.000002 | 461 |
+---------------+-----------+
セット内の 2 行 (0.00 秒)

これを手動で行うと、DUMP スレッドのインデックスファイルオフセットポインターが維持されないため、次のようになります。

このように、DUMP スレッドは binlog.000002 の内容を再送信し、POSITION のスレーブライブラリは次のようにエラーを報告することしかできません。

mysql> replication_applier_status_by_worker \G から * を選択します
************************** 1. 行 ****************************
     チャンネル名: 
      ワーカーID: 1
      スレッドID: NULL
    サービス状態: オフ
最後に確認された取引: 匿名
  最終エラー番号: 1062
  LAST_ERROR_MESSAGE: ワーカー 1 は、マスター ログ binlog.000002、end_log_pos 386 でトランザクション 'ANONYMOUS' の実行に失敗しました。テーブル testmts.testcp で Write_rows イベントを実行できませんでした。キー 'PRIMARY' のエントリ '20' が重複しています。Error_code: 1062。ハンドラー エラー HA_ERR_FOUND_DUPP_KEY。イベントのマスター ログ binlog.000002、end_log_pos 386
 最終エラータイムスタンプ: 2019-05-21 14:46:26

8. 結論

この操作は非常に不規則です。本当にこれを実行したい場合は、次の手順を検討してください。