Aurora MySQLからCloud SQLへのレプリケーション構築における注意すべき2つのポイント

f:id:vasilyjp:20210511124603p:plain

こんにちは、MA部でエンジニアをしている田島です。

以前に弊社の塩崎が「Amazon AuroraのデータをリアルタイムにGoogle BigQueryに連携してみた」という発表を行いました。

こちらの発表では、Amazon Aurora MySQLのデータをGoogle BigQueryへリアルタイムにデータ連携する方法を紹介しています。リアルタイムデータ連携を実現するために、Aurora MySQLをレプリケーションソースとしてGoogle Cloud SQLへレプリケーションします。そして、BigQueryのFederated Query機能を利用してリアルタイムにデータを参照できるようにしています。

本記事ではその中の、Aurora MySQLからCloud SQLへのレプリケーション部分にフォーカスします。Aurora MySQLがマネージドサービスだからこそ発生する大きな注意ポイントを2つ紹介します。

以降、以下の2つの注意ポイントを説明します。

  1. Aurora MySQLにおけるバイナリログの保持期間の設定
  2. Aurora MySQLのCollation

目次

リアルタイムデータ連携基盤

冒頭でも紹介しましたが、弊社のデータ基盤の一部では、Aurora MySQLのデータをGoogle BigQueryへリアルタイムにデータ連携をしてます。以前の発表内容をご覧になられていない方のために、改めてその概要を紹介します。発表または発表資料をご覧になられた方は読み飛ばして頂いて問題ありません。

リアルタイムデータ連携基盤の全体構成

以下がAurora MySQLからGoogle BigQueryへリアルタイムデータ連携をするための全体構成です。

f:id:vasilyjp:20210511124620p:plain

前述の通り、Aurora MySQLをレプリケーションソースとしCloud SQLへレプリケーションします。これにより、Aurora MySQLのデータがリアルタイムにCloud SQLへ連携されます。そして、BigQueryからCloud SQLへFederated Queryという機能を利用することでCloud SQLのデータをBigQueryから参照できます。

以上のようにしてAurora MySQLのデータをBigQueryからリアルタイムに参照することを可能としました。

その他の構成の特徴として、AWS-GCP間のインターナル通信を実現するために、弊社のオンプレ環境を挟み専用線を用いた通信を利用しています。また、冗長構成等も行っています。そのような全体構成の詳細は、改めて別の記事で紹介する予定です。

復習「MySQLのレプリケーション」

まずはMySQLのレプリケーションについて復習します。ここでは、レプリケーションされるサーバーを「メインDB」、レプリケーションするサーバーを「レプリカDB」と呼ぶこととします。本記事では、Aurora MySQLからGoogle Cloud SQLへのレプリケーションにおいて必要となる部分のみを抜粋して説明します。より細かくレプリケーションについて学びたい場合は以下の記事が非常に参考になります。

qiita.com

バイナリログとリレーログ

MySQLのレプリケーションはバイナリログと呼ばれるものを利用して実現します。

メインDBのすべての変更はバイナリログに保存されます。それらのバイナリログに書かれた変更点を別のDBで再現することにより、メインDBで行われた変更を追随できます。

続いて、保存されたバイナリログをレプリカDBに送ります。メインDBから送られてきたバイナリログをレプリカDBではリレーログと呼びます。レプリカDBはリレーログに書かれた変更点を取り込むことによってメインDBで起こった変更に追随します。こうすることにより、レプリカDBはメインDBと同期が取れた状態となります。

f:id:vasilyjp:20210511124632p:plain

バイナリログのローテーション

バイナリログのファイル名は以下のように「プレフィックス.インデックス」の形式を取ります。自前でMySQLを運用している場合は「--log-bin-index[=file_name]」オプションを利用することでファイル名のプレフィックスを変更できます。Amazon RDSを利用している場合は以下のような「MySQL-bin-changelog」がプレフィックスに利用されます。

mysql-bin-changelog.000001

また、バイナリログは以下のコマンドを利用することで確認可能です。実際に検証用のAurora MySQLで実行した結果が以下の通りです。

mysql> SHOW BINARY LOGS;
+----------------------------+-----------+
| Log_name                   | File_size |
+----------------------------+-----------+
| mysql-bin-changelog.003382 |   7335768 |
| mysql-bin-changelog.003383 |       194 |
| mysql-bin-changelog.003384 |  17682649 |
+----------------------------+-----------+

ここからわかるように、MySQL-bin-changelogのインデックスが「003382」から始まっており、「000001〜003381」が存在していません。これはバイナリログがローテーションされ、古いバイナリログが定期的に消されていることによります。

なお、MySQLにおいてバイナリログがローテーションされるタイミングは以下のように定義されています。

  • DB再起動時
  • max_binlog_sizeを超えたとき
  • RDSの場合はフェイルオーバー時も

また、バイナリログは以下のオプションを設定することで、定期的に削除できます。

expire_logs_days

オプションの詳細に関しては以下のドキュメントをご参照ください。

dev.mysql.com

また、Aurora MySQLでは、以下の例のような特別なパラメータを利用することでバイナリログの削除タイミングを設定可能です。

CALL mysql.rds_set_configuration('binlog retention hours', 24);

こちらも詳しくは以下のドキュメントをご参照ください。

aws.amazon.com

このように、バイナリログファイルはローテーションされ、古いログが削除されます。そのため、初めてレプリケーションを行う場合、バイナリログを利用するだけではメインDBの状態をレプリカDBに再現することはできません。

そこで、最初にメインDBのダンプを取得し、レプリカでそれをロードします。これによりバイナリログが存在する期間までの状態をレプリカで再現できます。あとは、その続きからバイナリログを利用して変更に追随することでメインDBの状態を再現できます。

GTID

先程の説明で「メインDBのダンプを取得し、レプリカでそれをロード」し「その続きからバイナリログを利用して変更に追随することでメインDBの状態を再現できます」と紹介しました。

しかし、どのように「その続きから」をMySQLは判断するのでしょうか。MySQLがどこまでの変更が反映されたのかを判断するためのIDとしてGTIDというものが存在します。 GTIDは以下のような形式のIDです。

b340ea24-7307-34f8-afac-7cabb90c910e:1
b340ea24-7307-34f8-afac-7cabb90c910e:2
b340ea24-7307-34f8-afac-7cabb90c910e:3

以下のコマンドを利用することで人間が読める形でバイナリログを取得できます。 SET @@SESSION.GTID_NEXT= 'b340ea24-7307-34f8-afac-7cabb90c910e:38'/*!*/; とGTIDが利用されていることがわかります。

 mysqlbinlog --read-from-remote-server --host=host_name --port=3306 --user username --password='xxxxxxxxxxx' -v mysql-bin-changelog.000001 > binlog.000001
$ cat binlog.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210121  6:03:16 server id 1678319257  end_log_pos 123 CRC32 0x828ddba9         Start: binlog v 4, server v 5.7.12-log created 210121  6:03:16 at startup
ROLLBACK/*!*/;
BINLOG '
JBkJYA+ZHglkdwAAAHsAAAAAAAQANS43LjEyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAkGQlgEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AanbjYI=
'/*!*/;
# at 123
#210121  6:03:16 server id 1678319257  end_log_pos 194 CRC32 0x00f6490d         Previous-GTIDs
# b340ea24-7307-34f8-afac-7cabb90c910e:1-37
# at 194
#210209  9:50:29 server id 1678319257  end_log_pos 259 CRC32 0x90246c84         GTID    last_committed=0        sequence_number=1     rbr_only=no
SET @@SESSION.GTID_NEXT= 'b340ea24-7307-34f8-afac-7cabb90c910e:38'/*!*/;
# at 259
#210209  9:50:29 server id 1678319257  end_log_pos 331 CRC32 0x6ef666ab         Query   thread_id=14    exec_time=0     error_code=0
SET TIMESTAMP=1612864229/*!*/;
SET @@session.pseudo_thread_id=14/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;

ここではGTIDを利用したレプリケーションを紹介しましたが、GTIDを使わない方法も存在します。また、GTIDはMySQL 5.6以上のバージョンでないと利用できません。今回はGTIDを利用したレプリケーションを前提とするため詳細は省略します。

レプリケーションの確認方法

レプリケーションの状態を確認するためには以下のコマンドを利用します。

SHOW SLAVE STATUS;

以下に示すのは、Aurora MySQLからレプリケーションした先のレプリカDBであるCloud SQLにおいて実行した結果です。レプリケーションが正常に動作している場合、以下のような出力となります。

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: main.host.name
                  Master_User: main_host_user
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin-changelog.000011
          Read_Master_Log_Pos: 42199452
               Relay_Log_File: relay-log.000006
                Relay_Log_Pos: 963
        Relay_Master_Log_File: mysql-bin-changelog.000011
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table: mysql.%
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 42199452
              Relay_Log_Space: 1455
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1678319257
                  Master_UUID: a9168178-6d44-3109-b13c-06fde20ea6cf
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:228240-228242
            Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-228242
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
       Master_public_key_path:
        Get_master_public_key: 0
            Network_Namespace:
1 row in set (0.15 sec)

出力結果で、以下のように Slave_IO_RunningSlave_SQL_Running がYesになっていれば、正常にレプリケーションが動作していることがわかります。

Slave_IO_Running: Yes
Slave_SQL_Running: Yes

また、バイナリログやリレーログに関するパラメータが表示されていることもわかります。

Master_Log_File: mysql-bin-changelog.000011
Read_Master_Log_Pos: 42199452
Relay_Log_File: relay-log.000006
Relay_Log_Pos: 963
Relay_Master_Log_File: mysql-bin-changelog.000011

GTIDに関するパラメータも表示されていて以下のような意味があります。

Retrieved_Gtid_Set: メインDBから受けっとって保持しているトランザクション。上記の場合 GTID 228240 〜 228242を保持している。1 〜 228239 を含むファイルは既に削除済み。
Executed_Gtid_Set: レプリカDBで既に実行したトランザクションを表す。上記の場合GTID 1 〜 228242 までレプリカDBに反映済み。

一方で、レプリケーションでエラー等が発生した場合は以下のような出力となります。

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: main.host.name
                  Master_User: main_host_user
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File:
          Read_Master_Log_Pos: 4
               Relay_Log_File: relay-log.000002
                Relay_Log_Pos: 4
        Relay_Master_Log_File:
             Slave_IO_Running: No
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table: mysql.%
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 0
              Relay_Log_Space: 331
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.'
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1678319257
                  Master_UUID: a9168178-6d44-3109-b13c-06fde20ea6cf
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp: 210209 10:52:51
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-36
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.15 sec)

Slave_IO_Running: No となり、レプリケーションが止まっていることがわかります。また、直前に発生したエラーは Last_IO_Error で確認できます。

Aurora MySQLからCloud SQLへのレプリケーション手順

以下の記事で、Aurora MySQLからCloud SQLへインターナル通信にてレプリケーションする方法をまとめています。

qiita.com

本記事ではこれらのうち、レプリケーションに関する部分のみを抜粋して改めて紹介します。

以下がレプリケーション構築の手順です。

  1. Aurora MySQLの設定
  2. Aurora MySQLの初期ダンプ
  3. Cloud SQLのレプリカ構築
  4. Cloud SQLにおいてダンプしたデータをロード
  5. Cloud SQLからAurora MySQLに対してレプリケーションを開始

上記の手順において、一部補足説明をします。

1. Aurora MySQLの設定

まずはじめに、外部へのレプリケーションが可能となるようにAurora MySQLの設定をします。以下のドキュメントにその手順が紹介されています。

docs.aws.amazon.com

また、以下のドキュメントに記載のある設定により、GTIDベースのレプリケーションを行うことができます。

docs.aws.amazon.com

2.〜3. Cloud SQLの構築

GCPにて以下のドキュメントに記載されている手順に従いCloud SQLを構築します。Cloud SQLにおけるレプリケーションではMySQLの初期ダンプは手動で行う方法と、自動で行う方法と両方用意されています。また、レプリカを構築するとダンプのロードからレプリケーションの開始まで自動で行ってくれます。

cloud.google.com

Aurora MySQLからCloud SQLへのレプリケーション構築における注意すべき2つのポイント

それではやっと本編です。Aurora MySQLからCloud SQLへレプリケーションする際の注意点を2つ紹介します。

(1)Aurora MySQLにおけるバイナリログの保持期間の設定

1つ目はAurora MySQLにおけるバイナリログの保持期間の設定の挙動についてです。

発生した問題

前述の通り、Aurora MySQLからCloud SQLへレプリケーションするには、初期ダンプを行い、そのデータをロードする必要があります。そのため、ダンプ開始からダンプのロード完了まで対象のバイナリログが残っていないと、ダンプ完了後に続きからレプリケーションを開始できなくなってしまいます。よって、バイナリログは「ダンプ時間 + ロード時間」だけ削除されずに残っている必要があります。そこで、実際の作業ではダンプ開始からダンプロード完了までに12時間くらいかかると予想し、バイナリログ保持期間を1日として作業しました。以下がその設定です。

CALL mysql.rds_set_configuration('binlog retention hours', 24);

実際に試したところ、想定通りダンプの取得からダンプのロード完了まで合わせて12時間で完了し、設定したバイナリログの保持期間に収めることができました。しかし、初期ダンプロード後にレプリケーションを開始すると以下のエラーが発生しました。

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: main.host.name
                  Master_User: main_host_user
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File:
          Read_Master_Log_Pos: 4
               Relay_Log_File: relay-log.000002
                Relay_Log_Pos: 4
        Relay_Master_Log_File:
             Slave_IO_Running: No
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table: mysql.%
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 0
              Relay_Log_Space: 331
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File:
           Master_SSL_CA_Path:
              Master_SSL_Cert:
            Master_SSL_Cipher:
               Master_SSL_Key:
        Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 1236
                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.'
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 117581704
                  Master_UUID: b340ea24-7307-34f8-afac-7cabb90c910e
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp: 210208 14:36:58
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set: b340ea24-7307-34f8-afac-7cabb90c910e:1-1024678
                Auto_Position: 1
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.16 sec)

上記のエラーは「対象のGTIDを含むバイナリログが見つからない」といったエラーでした。実際にバイナリログを確認すると、既に対象のGTIDを含むはずのバイナリログファイルがローテートされ削除されてしまっていました。なぜ、設定したバイナリログ保持期間よりも短い時間でバイナリログが消えていたのでしょうか。

結論

AWSの仕様を改めて確認すると以下のようにドキュメントに記載されています。

aws.amazon.com

この仕様を読んだ際には、最新のバイナリログ書き込みから、設定した保持期間分のバイナリログが保持されると考えていました。しかし、実際にはバイナリログの保持期間は「ログのファイルが生成されたタイミング」から指定した期間バイナリログが保持されるということが確認できました。そのため、対象バイナリログファイルがローテートされたタイミングで既にファイル作成時から保持期間を過ぎていた場合、即座にファイルが削除されてしまいます。

再現実験

実際にその挙動を実験で再現させました。

実験準備

まず初めに、3時間でbinlogが削除されるように設定します。

CALL mysql.rds_set_configuration('binlog retention hours', 3);

続いて以下のようなスクリプトを作成しました。

  • 定期的にデータをinsertするスクリプト
while true
do
        sleep 1
        mysql -h host_name -u root -Dtest -pxxxxx  -e " insert into user values (0, 'xxx');"
done
  • 15秒ごとにGTIDの状態を取得するスクリプト
while true
do
        date
        mysql -h host_name -u root -Dtest -pxxxxx  -e "SHOW GLOBAL VARIABLES LIKE '%gtid%';"
        mysql -h host_name -u root -Dtest -pxxxxx  -e "SHOW MASTER STATUS\\G"
        mysql -h host_name -u root -Dtest -pxxxxx  -e "SHOW BINARY LOGS\\G"
        sleep 15
done

以上のスクリプトを数時間実行し、そのログを解析します。

ログの解読

上記スクリプトによって出力されるログのうち、見るべきログを説明します。

  • gtid_executed
    • 最後の数字が最新のトランザクション(GTID)になっている(実行済みトランザクション)
  • gtid_purged
    • binlogから既に削除済みのトランザクション(GTID)
    • これを見ることで削除されてしまったトランザクションログがわかる
  • Log_name
    • binlogのファイル名でトランザクションログが書き出されるファイル
    • これを見ることでローテーションされたbinlogファイルが確認できる

実験結果

実験の結果を順に紹介します。

  • 上記スクリプトを「Tue Feb 9 14:28:33 UTC」から実行開始
Tue Feb  9 14:28:33 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-9172
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-37
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000007
         Position: 2393564
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-9172
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000007
File_size: 2393564
  • 10時間後の「Wed Feb 10 00:28:42 UTC 2021」
Wed Feb 10 00:28:42 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-43018
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-37
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000007
         Position: 11261216
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-43018
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000007
File_size: 11261216

トランザクション単位でbinlogが削除されるのであれば「gtid_purged」の値が変わっているはずです。しかし、実際には変わっていないことがわかります。よって、binlog保持期間を過ぎてもログは削除されていないことがわかりました。

  • 「Wed Feb 10 04:08:45 UTC 2021」

binlogをローテートさせるため、 メインDBのフェイルオーバーを実施します。

  • 「Wed Feb 10 04:18:45 UTC 2021」
Wed Feb 10 04:18:45 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-55967
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-55321
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000008
         Position: 169446
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-55967
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000008
File_size: 169446

ログローテートされてから数十秒後に000007のbinlogが削除されました。ここから、ローテート済みバイナリログファイルでないと削除されないことがわかります。

  • 「Wed Feb 10 05:02:55 UTC 2021」

再度フェイルオーバーを行い、バイナリログをローテートさせます。

  • 「Wed Feb 10 05:27:57 UTC 2021」
Wed Feb 10 05:27:57 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-59887
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-55321
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000009
         Position: 370400
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-59887
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000008
File_size: 826280
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000009
File_size: 370400

フェイルオーバーから数十秒経過しても古いバイナリログ000008が削除されていないことから、保持期間は何らかの形で働いていることがわかります。

  • 「Wed Feb 10 05:30:29 UTC 2021」

再現性を確認するために、再度フェイルオーバーを実施します。

  • Wed Feb 10 06:30:55 UTC 2021
Wed Feb 10 06:30:55 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-63482
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-55321
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000010
         Position: 914836
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-63482
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000008
File_size: 826280
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000009
File_size: 397648
*************************** 3. row ***************************
 Log_name: mysql-bin-changelog.000010
File_size: 914836

フェイルオーバーから数十秒経過しても000008、000009は削除されないことを確認しました。

  • 「Wed Feb 10 07:10:26 UTC 2021」
Wed Feb 10 07:10:11 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-65733
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-55321
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000010
         Position: 1504598
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-65733
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000008
File_size: 826280
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000009
File_size: 397648
*************************** 3. row ***************************
 Log_name: mysql-bin-changelog.000010
File_size: 1504598


Wed Feb 10 07:10:26 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-65747
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-58474
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000010
         Position: 1508266
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-65747
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000009
File_size: 397648
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000010
File_size: 1508266

このタイミングで000008が削除されました。「Wed Feb 10 04:08:45 UTC 2021」にbinlogが生成されたので、約3時間くらい経過しています。これはバイナリログ保持期間とほぼ同じタイミングです。

  • 「Wed Feb 10 08:05:36 UTC 2021」
Wed Feb 10 08:05:21 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-68879
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-58474
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000011
         Position: 447428
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-68879
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000009
File_size: 397648
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000010
File_size: 1881616
*************************** 3. row ***************************
 Log_name: mysql-bin-changelog.000011
File_size: 447428


Wed Feb 10 08:05:36 UTC 2021
mysql: [Warning] Using a password on the command line interface can be insecure.
Variable_name   Value
binlog_gtid_simple_recovery     ON
enforce_gtid_consistency        ON
gtid_executed   a9168178-6d44-3109-b13c-06fde20ea6cf:1-68893
gtid_executed_compression_period        1000
gtid_mode       ON
gtid_owned
gtid_purged     a9168178-6d44-3109-b13c-06fde20ea6cf:1-59991
session_track_gtids     OFF
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
             File: mysql-bin-changelog.000011
         Position: 451358
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: a9168178-6d44-3109-b13c-06fde20ea6cf:1-68894
mysql: [Warning] Using a password on the command line interface can be insecure.
*************************** 1. row ***************************
 Log_name: mysql-bin-changelog.000010
File_size: 1881616
*************************** 2. row ***************************
 Log_name: mysql-bin-changelog.000011
File_size: 451358

このタイミングで000009が削除されました。「Wed Feb 10 05:02:55 UTC 2021」から約3時間経過しているので、やはりバイナリログ保持期間とほぼ同じタイミングです。

以上の実験結果により、実際にバイナリログファイルが作成されてから指定した保持期間後に対象のバイナリログがローテートされている場合にのみ削除されることが確認・再現できました。

回避方法

上記の結果からわかるように、バイナリログファイルがログローテートされる前に保持期間を過ぎてしまった場合、ログローテートされたタイミングで即座にファイルが削除されてしまいます。

そこで、自分たちのシステムではどれくらいの期間で max_binlog_size に到達するのかを知る必要があります。これがわかったら「ダンプ取得 + ダンプロード」時間と「max_binlog_size に到達する」時間を比較し、ログ保持期間をその大きい方の値以上に設定することでログの消失を防ぐことができます。

(2)Aurora MySQLのCollation

2つ目の注意点はAurora MySQLのCollationについてです。

MySQLのCollation

MySQLはCharsetの他にCollationを指定できます。Collationは日本語では照合順序のことで文字の並び順のことです。これにより、どちらの文字の方が大きいのか小さいのかを判定します。また、文字を区別する際の役割も担っており、大文字と小文字「A」と「a」や濁点と半濁点「ば」と「ぱ」を同じ文字として認識するのかといったことはCollationによって異なります。

発生した問題

(1)の問題が解決し無事レプリケーションに成功した後、以下のエラーが発生しました。

Error 'Character set '#255' is not a compiled character set and is not specified in the '/usr/share/mysql/charsets/Index.xml' file' on query. Default database: 'database_name'. Query: 'create index idx_xxxx_yyyy on xxxx ( xxxx, yyyy)'

このエラーを調べたところ Charset ID #255 がCloud SQLには存在していないというエラーでした。これは CHARACTER_SET_NAME=utf8_mb4COLLATION_NAME=utf8mb4_0900_ai_ci という組み合わせでした。そして、utf8mb4_0900_ai_ci はMySQL 8.0から導入されたことがわかりました。

調査(1)メインDBのCollationの設定確認

メインDBであるAurora MySQLではバージョン5.7を利用しているため、Collation utf8mb4_0900_ai_ci は使われないと考えていました。実際に確認すると以下のCollationしか使われていませんでした。

utf8mb4_bin
utf8_general_ci

これらは以下のコマンドで調査しました。

-- データベースのCollationの確認
mysql> SHOW VARIABLES LIKE 'collation_server';
+----------------------+-------------------+
| Variable_name        | Value             |
+----------------------+-------------------+
| collation_connection | latin1_swedish_ci |
| collation_database   | utf8mb4_bin       |
| collation_server     | utf8mb4_bin       |
+----------------------+-------------------+

-- テーブルごとのCollationの確認
mysql> SHOW TABLE STATUS FROM データベース名 \G
*************************** 1. row ***************************
           Name: xxxxx
         Engine: InnoDB
        Version: 10
     Row_format: Dynamic
           Rows: 27
 Avg_row_length: 606
    Data_length: 16384
Max_data_length: 0
   Index_length: 16384
      Data_free: 0
 Auto_increment: NULL
    Create_time: 2021-02-12 07:34:57
    Update_time: 2021-04-05 06:24:30
     Check_time: NULL
      Collation: utf8mb4_bin
       Checksum: NULL
 Create_options:
        Comment:
                           (略)

-- カラムごとのCollationの確認
mysql> SELECT table_name, column_name, collation_name FROM columns WHERE table_schema='データベース名' AND collation_name IS NOT NULL;
+-----------------------+-----------------+-----------------+
| table_name            | column_name     | collation_name  |
+-----------------------+-----------------+-----------------+
| xxxxx                 | xxxxxxx         | utf8mb4_bin     |
| yyyyy                 | yyyyyyy         | utf8_general_ci |
                         (略)
+-----------------------+-----------------+-----------------+

調査(2)binlogの確認

続いて、実際にどのようなbinlogが生成されたことで、このエラーが発生したのかを確認します。対象のbinlogを確認すると以下のような怪しい部分が見つかりました。@@session.charset_client 並びに @@session.collation_connection255 にセットされていることが確認できます。

# at 80217401
#210212  1:17:30 server id 117581704  end_log_pos 80217607 CRC32 0x682b2d36     Query   thread_id=79799 exec_time=910   error_code=0
SET TIMESTAMP=1613092650.534322/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=46/*!*/;
create index xxxxxxxxxxxxxxx on xxxxxxxxxxxx (xxxxxx, yyyyyy)
/*!*/;

調査(3)Charset ID #255の確認

実際にメインDBで Charset ID #255 が使われていることがわかったため、Aurora MySQLにおける Charset ID #255 がどのようになっているかを確認しました。以下のコマンドで確認できます。

mysql> SELECT * FROM information_schema.collations WHERE id = 255;
+--------------------+--------------------+-----+------------+-------------+---------+
| COLLATION_NAME     | CHARACTER_SET_NAME | ID  | IS_DEFAULT | IS_COMPILED | SORTLEN |
+--------------------+--------------------+-----+------------+-------------+---------+
| utf8mb4_0900_ai_ci | utf8mb4            | 255 |            | Yes         |       0 |
+--------------------+--------------------+-----+------------+-------------+---------+
1 row in set (0.00 sec)

Charset ID #255 が存在し、Collationは utf8mb4_0900_ai_ci となっています。utf8mb4_0900_ai_ci は、MySQL 8.0から導入されたCollationでした。しかし、Aurora MySQLでは5.7バージョンにおいて先行してこのCollationが使えるとわかりました。また、Cloud SQLにおいて同じように確認すると、 Charset ID #255 が存在していないことがわかります。

mysql> SELECT * FROM information_schema.collations WHERE id = 255;
Empty set (0.15 sec)

調査(4)クライアント側でCollationを指定して再現実験

調査をすすめると、MySQLでは以下のコマンドでクライアント側から利用するCollationを指定可能であることがわかりました。

SET collation_connection = utf8mb4_0900_ai_ci;

そこで、検証環境のメインDB側でCollationを指定した場合と指定しなかった場合の挙動を確認します。書き込み処理は実際に本番環境でエラーが発生したインデックスの作成をしています。

mysql> SHOW VARIABLES LIKE 'collation%';
+----------------------+-------------------+
| Variable_name        | Value             |
+----------------------+-------------------+
| collation_connection | utf8_general_ci   |
| collation_database   | latin1_swedish_ci |
| collation_server     | latin1_swedish_ci |
+----------------------+-------------------+
3 rows in set (0.00 sec)

mysql> create index idx_user_id on user (id);
Query OK, 0 rows affected (0.61 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> SET collation_connection = utf8mb4_0900_ai_ci;
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW VARIABLES LIKE 'collation%';
+----------------------+--------------------+
| Variable_name        | Value              |
+----------------------+--------------------+
| collation_connection | utf8mb4_0900_ai_ci |
| collation_database   | latin1_swedish_ci  |
| collation_server     | latin1_swedish_ci  |
+----------------------+--------------------+
3 rows in set (0.00 sec)

mysql> create index idx_user_name on user (name);

すると、以下のようなバイナリログが出力されました。

  • Collation指定前
# at 42198999
#210215  2:14:50 server id 1678319257  end_log_pos 42199110 CRC32 0x37819efd    Query   thread_id=194567        exec_time=1     error_code=0
SET TIMESTAMP=1613355290/*!*/;
create index idx_user_id on user (id)
/*!*/;
  • Collation指定後
# at 42199175
#210215  2:15:16 server id 1678319257  end_log_pos 42199290 CRC32 0x328a35c9    Query   thread_id=194567        exec_time=0     error_code=0
SET TIMESTAMP=1613355316/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=255,@@session.collation_server=8/*!*/;
create index idx_user_name on user (name)
/*!*/

以上の結果から、確かにバイナリログに @@session.collation_connection=255 がセットされていることがわかります。また、レプリケーションも同様のエラーが発生し、事象の再現に成功しました。

調査(5)session.collation_connectionが255にセットされた原因の調査

ここまでの調査により、クライアント側でCollationをセットすることで、バイナリログにもその変更が反映されることがわかりました。しかし、わざわざCollationをクライアント側でセットしていませんでした。クライアント側のCollationのデフォルト値について調査したところ、ロケールを以下のように設定した環境においてMySQL 8.0クライアントを利用するとデフォルトで utf8mb4_0900_ai_ci のCollationが使われるとわかりました。

export LANG=ja_JP.UTF-8;localedef -f UTF-8 -i ja_JP ja_JP.utf8
mysql> SHOW VARIABLES LIKE 'collation%';
+----------------------+--------------------+
| Variable_name        | Value              |
+----------------------+--------------------+
| collation_connection | utf8mb4_0900_ai_ci |
| collation_database   | utf8mb4_bin        |
| collation_server     | utf8mb4_bin        |
+----------------------+--------------------+

この状態で書き込みを行うと、実際にコマンドからCollationをセットしたときと同様のバイナリログが出力されました。また、Collationの詳細な挙動は以下のドキュメントをご参照ください。

dev.mysql.com

結論

以上の調査結果から、Collation utf8mb4_0900_ai_ci が利用できるAurora MySQL環境において、Collationを指定して書き込みを行うことでバイナリログに以下が書き出されることがわかりました。

@@session.collation_connection=255

そして、これをCloud SQL側で読み取ると対象のCollationが存在しないためエラーが発生します。また、Collationを意図的に指定しなくても、MySQL 8.0クライアントを利用しロケールを適切にセットするとデフォルトで utf8mb4_0900_ai_ci が利用されることもわかりました。

回避方法

回避方法として、クライアント側で必ずCollationを確認することは可能ですが、意図せずCollationの設定にミスがあるとそのタイミングでレプリケーションが止まってしまいます。そのため、システム側で解決する必要があります。

最初にCloud SQLへ対象のCollationを追加することを考えました。しかし、Cloud SQLの特性上Collationの追加はできないことがわかりました。

そこで、Cloud SQL側のMySQLのバージョンを8.0とすることで回避しました。Collation以外の部分で非互換な部分はありますが、現在の運用方法では特にバージョン違いが原因による問題は発生していません。実際にこのような構成を採用する場合は事前に使っている機能に互換性があるか確認することをおすすめします。

まとめ

本記事では、Auroara MySQLからCloud SQLへのレプリケーションにおいて注意すべき点を2点紹介しました。

弊社では、エラーを1つずつ調査し、妥協せずに解決まで導き出せるエンジニアを募集しています。興味がありましたら以下のリンクからご応募ください。

tech.zozo.com

カテゴリー