こんにちは、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つの注意ポイントを説明します。
- Aurora MySQLにおけるバイナリログの保持期間の設定
- Aurora MySQLのCollation
目次
- 目次
- リアルタイムデータ連携基盤
- 復習「MySQLのレプリケーション」
- Aurora MySQLからCloud SQLへのレプリケーション手順
- Aurora MySQLからCloud SQLへのレプリケーション構築における注意すべき2つのポイント
- まとめ
リアルタイムデータ連携基盤
冒頭でも紹介しましたが、弊社のデータ基盤の一部では、Aurora MySQLのデータをGoogle BigQueryへリアルタイムにデータ連携をしてます。以前の発表内容をご覧になられていない方のために、改めてその概要を紹介します。発表または発表資料をご覧になられた方は読み飛ばして頂いて問題ありません。
リアルタイムデータ連携基盤の全体構成
以下がAurora MySQLからGoogle BigQueryへリアルタイムデータ連携をするための全体構成です。
前述の通り、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へのレプリケーションにおいて必要となる部分のみを抜粋して説明します。より細かくレプリケーションについて学びたい場合は以下の記事が非常に参考になります。
バイナリログとリレーログ
MySQLのレプリケーションはバイナリログと呼ばれるものを利用して実現します。
メインDBのすべての変更はバイナリログに保存されます。それらのバイナリログに書かれた変更点を別のDBで再現することにより、メインDBで行われた変更を追随できます。
続いて、保存されたバイナリログをレプリカDBに送ります。メインDBから送られてきたバイナリログをレプリカDBではリレーログと呼びます。レプリカDBはリレーログに書かれた変更点を取り込むことによってメインDBで起こった変更に追随します。こうすることにより、レプリカDBはメインDBと同期が取れた状態となります。
バイナリログのローテーション
バイナリログのファイル名は以下のように「プレフィックス.インデックス」の形式を取ります。自前で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
オプションの詳細に関しては以下のドキュメントをご参照ください。
また、Aurora MySQLでは、以下の例のような特別なパラメータを利用することでバイナリログの削除タイミングを設定可能です。
CALL mysql.rds_set_configuration('binlog retention hours', 24);
こちらも詳しくは以下のドキュメントをご参照ください。
このように、バイナリログファイルはローテーションされ、古いログが削除されます。そのため、初めてレプリケーションを行う場合、バイナリログを利用するだけではメイン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_Running と Slave_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へインターナル通信にてレプリケーションする方法をまとめています。
本記事ではこれらのうち、レプリケーションに関する部分のみを抜粋して改めて紹介します。
以下がレプリケーション構築の手順です。
- Aurora MySQLの設定
- Aurora MySQLの初期ダンプ
- Cloud SQLのレプリカ構築
- Cloud SQLにおいてダンプしたデータをロード
- Cloud SQLからAurora MySQLに対してレプリケーションを開始
上記の手順において、一部補足説明をします。
1. Aurora MySQLの設定
まずはじめに、外部へのレプリケーションが可能となるようにAurora MySQLの設定をします。以下のドキュメントにその手順が紹介されています。
また、以下のドキュメントに記載のある設定により、GTIDベースのレプリケーションを行うことができます。
2.〜3. Cloud SQLの構築
GCPにて以下のドキュメントに記載されている手順に従いCloud SQLを構築します。Cloud SQLにおけるレプリケーションではMySQLの初期ダンプは手動で行う方法と、自動で行う方法と両方用意されています。また、レプリカを構築するとダンプのロードからレプリケーションの開始まで自動で行ってくれます。
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の仕様を改めて確認すると以下のようにドキュメントに記載されています。
この仕様を読んだ際には、最新のバイナリログ書き込みから、設定した保持期間分のバイナリログが保持されると考えていました。しかし、実際にはバイナリログの保持期間は「ログのファイルが生成されたタイミング」から指定した期間バイナリログが保持されるということが確認できました。そのため、対象バイナリログファイルがローテートされたタイミングで既にファイル作成時から保持期間を過ぎていた場合、即座にファイルが削除されてしまいます。
再現実験
実際にその挙動を実験で再現させました。
実験準備
まず初めに、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_mb4、COLLATION_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_connection が 255 にセットされていることが確認できます。
# 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の詳細な挙動は以下のドキュメントをご参照ください。
結論
以上の調査結果から、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つずつ調査し、妥協せずに解決まで導き出せるエンジニアを募集しています。興味がありましたら以下のリンクからご応募ください。
