マスター、スレーブ構成のMySQL環境でサービス稼動してる時には、レプリケーションの遅延がよく発生します。MySQLのスレーブはマスターの更新をシングルスレッドで処理するため、特定のSQL文(1つのDELETE文で大量のレコードの削除や、1つのUPDATE文で大量のレコードの更新など)がレプリケーションの遅延原因となることが多いです。
今回は現在進行形で遅延しているSQL文の調査方法と、過去に遅延したSQL文の調査方法をご紹介します。
はじめに環境構築
MySQL5.6インストール
今回はマスター/スレーブ構成にするため2台のサーバを用意し、yumでMySQLをインストールしてみます(OSはCentOS6.6) 。
MySQL Yum Repositoryをインストールします。
wget http://dev.mysql.com/get/mysql57-community-release-el6-8.noarch.rpm
rpm -i mysql57-community-release-el6-8.noarch.rpm
デフォルトではMySQL5.6ではなくMySQL5.7をインストールしてしまうので、mysql-community.repoの[mysql57-community]のenabledを0へ変更し、[mysql56-community]のenabledを1へ変更します。yumでMySQL5.6をインストールします。
vim /etc/yum.repos.d/mysql-community.repo
# Enable to use MySQL 5.6
[mysql56-community]
name=MySQL 5.6 Community Server
baseurl=http://repo.mysql.com/yum/mysql-5.6-community/el/6/$basearch/
enabled=1
gpgcheck=1
gpgkey=file:///etc/pki/rpm-gpg/RPM-GPG-KEY-mysql
[mysql57-community]
name=MySQL 5.7 Community Server
baseurl=http://repo.mysql.com/yum/mysql-5.7-community/el/6/$basearch/
enabled=0
gpgcheck=1
gpgkey=file:///etc/pki/rpm-gpg/RPM-GPG-KEY-mysql
yum install mysql-community-server
レプリケーションを行うためにMySQLの設定ファイル(my.cnf)を修正します。
バイナリログを有効にします。
マスター側はserver-id=1、スレーブ側はserver-id=2と追記します。
vim /etc/my.cnf
[mysqld]
log-bin=mysql-bin
server-id=1
MySQLを起動します。
/etc/init.d/mysqld start
構成は以下の通りです。
IP MySQL PORT master/slave 192.168.0.1 3306 master
192.168.0.2 3306 slave
レプリケーション設定
今回はMySQL5.6からの新機能GTIDなどは使用せずに、従来のログポジションを指定するレプリケーション設定で構成します。
マスターの設定
まずはレプリケーション用のユーザと権限を設定します(ユーザ名:repl、パスワード:replication) 。
mysql> CREATE USER 'repl'@'192.168.0.2' IDENTIFIED BY 'replication';
mysql> GRANT REPLICATION SLAVE ON *.* TO 'repl'@'192.168.0.2';
そして、現在のバイナリログの情報を取得しておきましょう。
mysql> SHOW MASTER STATUS;
+------------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000003 | 439 | | | |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)
スレーブの設定
スレーブ側でレプリケーションを開始します。
CHANGE MASTER TO
MASTER_PORT= 3306,
MASTER_HOST='192.168.0.1',
MASTER_USER='repl',
MASTER_PASSWORD='replication',
MASTER_LOG_FILE='mysql-bin.000003',
MASTER_LOG_POS=439;
mysql> START SLAVE;
Query OK, 0 rows affected (0.01 sec)
オプション値 値 説明
MASTER_PORT 3306 マスターのポート番号
MASTER_HOST 192.168.0.1 マスターのIPアドレス
MASTER_USER repl レプリケーション用のユーザ
MASTER_PASSWORD replication レプリケーション用のユーザのパスワード
MASTER_LOG_FILE mysql-bin.000003 マスターで確認したバイナリログ
MASTER_LOG_POS 439 マスターで確認したバイナリログポジション
正常にレプリケーションが開始されているかは「SHOW SLAVE STATUS\G」の以下の値がYESになっているか確認します。
Slave_IO_Running
Slave_SQL_Running
mysql> SHOW SLAVE STATUS\G
:
:
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
:
:
以上でレプリケーションの設定は完了です。
仮データの準備
マスターでデータベースを作成します。ここではreplというデータベースを作成しています。
mysql> create database repl;
Query OK, 1 row affected (0.00 sec)
mysql> use repl;
Database changed
テーブルを作成します。
mysql> create table repl_test (id serial,id2 int ,tx text);
Query OK, 0 rows affected (0.26 sec)
仮データを投入します。今回は簡単なプロシージャを作ってデータをインサートします。
delimiter //
DROP PROCEDURE IF EXISTS ins_repl_test//
CREATE PROCEDURE ins_repl_test ( num int)
BEGIN
DECLARE cnt int DEFAULT 1;
START TRANSACTION;
WHILE cnt <= num DO
INSERT INTO repl_test(id2,tx) values (mod(cnt,5),'TEST_TEXT');
SET cnt = cnt + 1;
END WHILE;
COMMIT;
END
//
delimiter ;
プロシージャの内容として、引数で指定された値だけ、テーブルにINSERTします。投入するデータのうち、ID列はオートインクリメントが設定されているため指定していません。ID2列には、ループを実行した回数の5で割った余りを挿入します。TX列はTEST_TEXT
という文字列を挿入します。
プロシージャを実行して1000000行のデータを登録します。
mysql> CALL ins_repl_test(1000000);
Query OK, 0 rows affected (8.96 sec)
CALL句の後に、先ほど作成したプロシージャ名と引数に挿入するデータ件数を指定しています。
スレーブにデータがレプリケーションされていることを確認します。スレープでSELECT文を実行します。
mysql> select count(*) from repl_test;
+----------+
| count(*) |
+----------+
| 1000000 |
+----------+
1 row in set (0.03 sec)
これで初期設定は完了です。
レプリケーション遅延調査方法
基本的にMySQLのレプリケーションは非同期のデータ転送のためマスターはスレーブが遅延しているかいないかは意識していません。 よって、レプリケーションの遅延を確認するには対象のスレーブを確認します。
現在進行形で遅延しているSQL文の調査方法
現在進行形で遅延が発生しているか調べる方法として、まずはSHOW SLAVE STATUSを確認します。表示された列のSeconds_Behind_Masterという値を確認することで遅延状態がわかります。単位は秒で、0であれば遅延していないということになります。
では、遅延を発生させるために先ほど追加したデータの全件をマスターで削除します。
mysql> delete from repl_test ;
Query OK, 1000000 rows affected (12.92 sec)
上記実行中にスレーブのSeconds_Behind_Masterの値を確認します。
mysql> show slave status\G
Seconds_Behind_Master: 5
Seconds_Behind_Masterの値が5となり5秒間の遅延が発生していることがわかります。
では、どのSQL文が遅延を発生させていたのか確認します。そのためにはSHOW PROCESSLISTを実行します。上記の遅延が発生している間にSHOW PROCESSLISTをスレーブで実行したものが以下になります。
mysql> show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------+
| 1 | system user | | NULL | Connect | 3792 | Waiting for master to send event | NULL |
| 2 | system user | | repl | Connect | 11 | updating | delete from repl_test |
| 5 | root | localhost | NULL | Query | 0 | init | show processlist |
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------+
ここから、どのSQL文が遅延をさせているかがわかります。
過去に遅延したSQL文の調査方法
過去遅延していてすでに遅延が解消されていた場合に対象のSQL文を確認する方法をご紹介します。
スレーブのMySQL設定ファイル(my.cnf)にlog-slave-updatesを追記して有効化
mysqlbinlogユーティリティーを使用してバイナリログから調査
という流れになります。スレーブのmy.cnfにlog-slave-updatesを追記してMySQLの再起動を行います。
vim /etc/my.cnf
[mysqld]
log-bin=mysql-bin
server-id=2
log-slave-updates
log-slave-updatesを有効にすることで、マスターから受け取った更新がスレーブ独自のバイナリログに出力されるようになります。log-slave-updatesはこうすることで、マスター/スレーブのカスケードレプリケーションを可能にできるサーバ変数です。
次にマスターで遅延を発生させる全件更新のUPDATE文を実行します。先ほどのテーブルは全件DELETEしてしまったので、プロシージャを使用して次は5000000件のデータを挿入後、UPDATE文を実行します。
mysql> call ins_repl_test(5000000);
mysql> update repl_test set id2=100;
Query OK, 5000000 rows affected (1 min 22.70 sec)
Rows matched: 5000000 Changed: 5000000 Warnings: 0
スレーブのSeconds_Behind_Masterの値が0になるのを待ちます。
mysql> show slave status\G
Seconds_Behind_Master: 0
ここからmysqlbinlogユーティリティを使用してスレーブのバイナリログから遅延を調査します。mysqlbinlogユーティリティとは、データベースの内容に対する変更を記述する「イベント」を含むファイルのバイナリログの内容をテキスト形式で表示するためのツールです。各種オプションで出力方法の変更が可能です。詳しくは以下マニュアルをご参照ください。
# mysqlbinlog mysql-bin.000005
:
:
#160513 8:59:39 server id 1 end_log_pos 301 CRC32 0xd44db1e3 Query thread_id=4 exec_time=467 error_code=0
use `repl`/*!*/;
SET TIMESTAMP=1463129979/*!*/;
update repl_test set id2=100
/*!*/;
# at 301
#160513 8:59:39 server id 1 end_log_pos 332 CRC32 0x4430c7d2 Xid = 7000266
COMMIT/*!*/;
DELIMITER ;
# End of log file
:
:
先ほど実行したUPDATE文の表示のある記述を抜き出しています。その中のexec_time
を確認します。このexec_timeは、マスターのバイナリログではイベントの実行にかかった時間 を表します。スレーブのバイナリログではスレーブでの実行終了時間からマスターでの実行開始時間を引いた差分 が表示されます。
上の内容ではexec_time=467
となっており、マスターでの実行時間1 min 22.70 sec(約83秒)なので、467秒-83秒=384秒のマスターとの遅延が発生していることがわかります。運用中ではマスターでの実行時間はわからないかもしれませんが、スレーブのバイナリログのexec_timeが明らかに大きいSQLは遅延の原因であるといえます。このようにスレーブのバイナリログから過去の遅延を調査することが可能です。
注意
障害などでレプリケーションが停止していた場合(特にIO_Thread)は、もちろんexec_timeが大きくなるので、スレーブ遅延の調査時はレプリケーションが正しくされている状態であることは必須となります。
[例]IO_Thread停止していた場合
スレーブでIO_Thread停止
mysql> stop slave io_thread;
Query OK, 0 rows affected (0.02 sec)
マスターでinsert文
mysql> insert into repl_test(id2,tx) values (888,'Iothread does not work');
Query OK, 1 row affected (0.20 sec)
1分後、スレーブでIO_Threadを起動しバイナリログを確認すると、以下のようになります。
#160607 3:21:52 server id 1 end_log_pos 774 CRC32 0x57c11014 Query thread_id=13 exec_time=87 error_code=0
SET TIMESTAMP=1465269712/*!*/;
insert into repl_test(id2,tx) values (888,'Iothread does not work')
insert自体は0.02 secで完了していますが、レプリケーションが停止していた分だけの時間も加算されているため、exec_time=87となってしまいます。
まとめ
現在のスレープの遅延は、SHOW SLAVE STATUSとSHOW PROCESSLISTから確認できます。過去のスレーブの遅延は、log-slave-updatesを有効にしてバイナリログから確認できます。