共计 114331 个字符，预计需要花费 286 分钟才能阅读完成。
集群信息
角色 IP 地址 ServerID 类型
Master 192.168.244.10 1 写入
Candicate master 192.168.244.20 2 读
Slave 192.168.244.30 3 读
Monitor host 192.168.244.40 监控集群组
MHA 具体的搭建步骤和原理，可参考另外一篇文章：
MySQL 高可用方案 MHA 的部署和原理 http://www.linuxidc.com/Linux/2017-05/144086.htm
自动 Failover
为了通过 MHA 的日志清晰判断 MHA 自动 Failover 的实现原理，需模拟如下场景：
当主库发生故障时，master 中还有一部分 binlog 日志没有传输到 Candicate master 和 Slave 上，且 Slave 上的二进制日志多于 Candicate master 上。
尝试了几种方案，总算如愿以偿。
方案一：
1. 关闭 Candicate master 和 Slave 的主从复制。
2. 通过存储过程生成测试数据
3. 开启 Candicate master 和 Slave 的主从复制并 kill 掉 master 的 mysqld 进程，模拟主库发生故障，进行自动 failover 操作
为此，还特意写了个脚本，可惜的是，效果并不理想，在自动 Failover 的过程中，显示 MHA Manager 到 master 的“SSH is NOT reachable”。
方案二：
通过 tc 命令对 Candicate master 和 Slave 的网卡分别设置不同的传输速率，确保发送到 Candicate master 的日志量小于 Slave 上的。
很可惜，效果同方案一一样。
方案三：
在主从复制中，直接关闭 master 的 mysqld 数据库。
但是，通过这样方式，并不会实现 Slave 上的二进制日志多于 Candicate master 的效果。
方案四：
通过截取 relay log，在关掉 slave 的情况下，修改 master.info 和 relay-log.info 的位置点来人为制造 Candicate master 的日志量小于 Slave 的。
事后想想，其实这样的方法就等同于先关闭 Candicate master 的主从复制，再在 master 上执行一段操作，再关闭 slave 上的主从复制，再在 master 上执行一段操作。
这样不就实现了 master 的 binlog > slave 的 relay log > Candicate master 的 relay log。
方案四总算如愿以偿
下面通过方案四看看 MHA 的实现原理
1. 创建测试表，并插入测试数据
2. 分别查看 master 上 binlog 的内容，slave 上 relay log 的内容
Master
mysql> show binlog events;
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
| mysql-bin.000001 | 4 | Format_desc | 1 | 120 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysql-bin.000001 | 120 | Query | 1 | 238 | create table sbtest.b(id int,name varchar(10)) |
| mysql-bin.000001 | 238 | Query | 1 | 315 | BEGIN |
| mysql-bin.000001 | 315 | Query | 1 | 421 | insert into sbtest.b values(1,'a') |
| mysql-bin.000001 | 421 | Xid | 1 | 452 | COMMIT /* xid=102 */ |
| mysql-bin.000001 | 452 | Query | 1 | 529 | BEGIN |
| mysql-bin.000001 | 529 | Query | 1 | 635 | insert into sbtest.b values(2,'b') |
| mysql-bin.000001 | 635 | Xid | 1 | 666 | COMMIT /* xid=103 */ |
| mysql-bin.000001 | 666 | Query | 1 | 743 | BEGIN |
| mysql-bin.000001 | 743 | Query | 1 | 849 | insert into sbtest.b values(3,'c') |
| mysql-bin.000001 | 849 | Xid | 1 | 880 | COMMIT /* xid=104 */ |
| mysql-bin.000001 | 880 | Query | 1 | 957 | BEGIN |
| mysql-bin.000001 | 957 | Query | 1 | 1063 | insert into sbtest.b values(4,'d') |
| mysql-bin.000001 | 1063 | Xid | 1 | 1094 | COMMIT /* xid=105 */ |
| mysql-bin.000001 | 1094 | Query | 1 | 1171 | BEGIN |
| mysql-bin.000001 | 1171 | Query | 1 | 1277 | insert into sbtest.b values(5,'e') |
| mysql-bin.000001 | 1277 | Xid | 1 | 1308 | COMMIT /* xid=106 */ |
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
17 rows in set (0.01 sec)Slave
mysql> show relaylog events in 'mysqld-relay-bin.000002';
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
| mysqld-relay-bin.000002 | 4 | Format_desc | 2 | 120 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysqld-relay-bin.000002 | 120 | Rotate | 1 | 0 | mysql-bin.000001;pos=120 |
| mysqld-relay-bin.000002 | 167 | Format_desc | 1 | 0 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysqld-relay-bin.000002 | 283 | Query | 1 | 238 | create table sbtest.b(id int,name varchar(10)) |
| mysqld-relay-bin.000002 | 401 | Query | 1 | 315 | BEGIN |
| mysqld-relay-bin.000002 | 478 | Query | 1 | 421 | insert into sbtest.b values(1,'a') |
| mysqld-relay-bin.000002 | 584 | Xid | 1 | 452 | COMMIT /* xid=102 */ |
| mysqld-relay-bin.000002 | 615 | Query | 1 | 529 | BEGIN |
| mysqld-relay-bin.000002 | 692 | Query | 1 | 635 | insert into sbtest.b values(2,'b') |
| mysqld-relay-bin.000002 | 798 | Xid | 1 | 666 | COMMIT /* xid=103 */ |
| mysqld-relay-bin.000002 | 829 | Query | 1 | 743 | BEGIN |
| mysqld-relay-bin.000002 | 906 | Query | 1 | 849 | insert into sbtest.b values(3,'c') |
| mysqld-relay-bin.000002 | 1012 | Xid | 1 | 880 | COMMIT /* xid=104 */ |
| mysqld-relay-bin.000002 | 1043 | Query | 1 | 957 | BEGIN |
| mysqld-relay-bin.000002 | 1120 | Query | 1 | 1063 | insert into sbtest.b values(4,'d') |
| mysqld-relay-bin.000002 | 1226 | Xid | 1 | 1094 | COMMIT /* xid=105 */ |
| mysqld-relay-bin.000002 | 1257 | Query | 1 | 1171 | BEGIN |
| mysqld-relay-bin.000002 | 1334 | Query | 1 | 1277 | insert into sbtest.b values(5,'e') |
| mysqld-relay-bin.000002 | 1440 | Xid | 1 | 1308 | COMMIT /* xid=106 */ |
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
19 rows in set (0.00 sec)通过对比 master 中的 binlog event，可以看到 show relaylog events 中的 End_log_pos 实际上指的是对应的二进制事件在 binlog 的位置。
再来查看 Candicate master 中对应的 relay log 的内容
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170524 17:16:37 server id 2 end_log_pos 120 CRC32 0x4faba9ae Start: binlog v 4, server v 5.6.31-log created 170524 17:16:37
BINLOG 'dU8lWQ8CAAAAdAAAAHgAAABAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAa6p
q08=
'/*!*/;
# at 120
#700101 8:00:00 server id 1 end_log_pos 0 CRC32 0x74c6d70c Rotate to mysql-bin.000001 pos: 120
# at 167
#170524 17:15:49 server id 1 end_log_pos 0 CRC32 0xed2672eb Start: binlog v 4, server v 5.6.31-log created 170524 17:15:49
BINLOG 'RU8lWQ8BAAAAdAAAAAAAAAAAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAety
Ju0=
'/*!*/;
# at 283
#170524 17:17:20 server id 1 end_log_pos 238 CRC32 0xdd48c118 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617440/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table sbtest.b(id int,name varchar(10))
/*!*/;
# at 401
#170524 17:17:27 server id 1 end_log_pos 315 CRC32 0xae393750 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617447/*!*/;
BEGIN
/*!*/;
# at 478
#170524 17:17:27 server id 1 end_log_pos 421 CRC32 0x28a781ae Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617447/*!*/;
insert into sbtest.b values(1,'a')
/*!*/;
# at 584
#170524 17:17:27 server id 1 end_log_pos 452 CRC32 0x680f1bfe Xid = 29
COMMIT/*!*/;
# at 615
#170524 17:17:33 server id 1 end_log_pos 529 CRC32 0x6a1aae7e Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617453/*!*/;
BEGIN
/*!*/;
# at 692
#170524 17:17:33 server id 1 end_log_pos 635 CRC32 0x117786ca Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617453/*!*/;
insert into sbtest.b values(2,'b')
/*!*/;
# at 798
#170524 17:17:33 server id 1 end_log_pos 666 CRC32 0xa8400ec6 Xid = 30
COMMIT/*!*/;
# at 829
#170524 17:17:38 server id 1 end_log_pos 743 CRC32 0x24f9a1d2 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617458/*!*/;
BEGIN
/*!*/;
# at 906
#170524 17:17:38 server id 1 end_log_pos 849 CRC32 0x56fa9e89 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617458/*!*/;
insert into sbtest.b values(3,'c')
/*!*/;
# at 1012
#170524 17:17:38 server id 1 end_log_pos 880 CRC32 0x2ac656d4 Xid = 31
COMMIT/*!*/;
# at 1043
#170524 17:17:44 server id 1 end_log_pos 957 CRC32 0x73a903bf Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617464/*!*/;
BEGIN
/*!*/;
# at 1120
#170524 17:17:44 server id 1 end_log_pos 1063 CRC32 0x171b9b27 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617464/*!*/;
insert into sbtest.b values(4,'d')
/*!*/;
# at 1226
#170524 17:17:44 server id 1 end_log_pos 1094 CRC32 0x47d6fe57 Xid = 32
COMMIT/*!*/;
# at 1257
#170524 17:17:49 server id 1 end_log_pos 1171 CRC32 0x2d37da37 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617469/*!*/;
BEGIN
/*!*/;
# at 1334
#170524 17:17:49 server id 1 end_log_pos 1277 CRC32 0xd2201fa2 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617469/*!*/;
insert into sbtest.b values(5,'e')
/*!*/;
# at 1440
#170524 17:17:49 server id 1 end_log_pos 1308 CRC32 0xac1b464e Xid = 33
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;mysql 中 binlog 有个有意思的地方是，位置点其实是也是字节的大小。
譬如，上面这个 relay log 中，最后一个位点是# at 1440，算上最后一个 commit 操作需占用 31 个字节，所以整个文件的大小是 1471，与实际大小吻合。
[root@node2 mysql]# ll mysqld-relay-bin.000002
-rw-rw---- 1 mysql mysql 1471 May 24 17:17 mysqld-relay-bin.0000023. 通过 show slave status 查看 io thread 和 sql thread 的位置信息
待会儿需要修改上面 Master_Log_File,Read_Master_Log_Pos,Relay_Log_File,Relay_Log_Pos,Relay_Master_Log_File,Exec_Master_Log_Pos 的值。
虽然这几个参数的值与 master.info 和 relay-log.info 文件是相对应的，
但通过修改 master.info 和 relay-log.info 的值，并重启 slave，并不会将上述几个参数值修改。
上述几个参数是保存到内存中的，唯一可行的方案是首先关闭 slave 实例，再修改 master.info 和 relay-log.info 文件，然后重新启动 mysql 实例。
4. 关闭 Candicate master 实例，剪裁 relay log，修改 master.info 和 relay-log.info 文件。
关闭实例
[root@node2 mysql]# service mysqld stop
剪裁 relay log
这里，写了个 Python 脚本实现该功能
在上述脚本 size1 中，615 对应的是 insert into sbtest.b values(1,’a’) 这条记录
[root@node2 mysql]# python 1.py
[root@node2 mysql]# mv tmp_relay_bin mysqld-relay-bin.000002
修改 master.info 的内容
主要是修改第三行
23
mysql-bin.000001
1308修改为
23
mysql-bin.000001
452修改 relay-log.info 的内容
原文件如下：
7
./mysqld-relay-bin.000002
1471
mysql-bin.000001
1308
0
0
1修改为：
7
./mysqld-relay-bin.000002
615
mysql-bin.000001
452
0
0
1启动 slave，注意，配置文件中必须设置 skip-slave-start，不然它自动开启主从复制。
[root@node2 mysql]# service mysqld start
5. 对于 slave，同样如此处理，只不过 relay log 的位置点要靠后些
#!/usr/bin/python
f1 = open('mysqld-relay-bin.000002','r')
f2 = open('tmp_relay_bin','w+')
size1=f1.read(1043)
f2.write(size1)
f1.seek(1471)
size2=f1.read()
f2.write(size2)
f1.close()
f2.close()1043 对应的是 insert into sbtest.b values(3,’c’) 这条记录
修改 master.info 的内容
23
mysql-bin.000001
880修改 relay-log.info 的内容
7
./mysqld-relay-bin.000002
1043
mysql-bin.000001
880
0
0
1 6. 开启 MHA 监控
# nohup masterha_manager –conf=/etc/masterha/app1.cnf –remove_dead_master_conf –ignore_last_failover < /dev/null >
/masterha/app1/manager.log 2>&1 &
# masterha_check_status –conf=/etc/masterha/app1.cnf
app1 (pid:1615) is running(0:PING_OK), master:192.168.244.107. 关闭 master 实例
# service mysqld stop
8. 查看 MHA 切换日志，了解整个切换过程。
该日志的时间点与上面 relay log 的时间点并不吻合，原因在于这个反复测试了很多次。
从上面的日志输出可以看出整个 MHA 的切换过程
首先，MHA Manager 检测到 master 不可用，则会通过另外两个 slave 检查 master 的可用性。一共检测 4 次。
同时判断 MHA Manager 到 master 的 ssh 可用性。
ssh 可用性的判断结果影响后后续切换中的“Phase 3.2: Saving Dead Master’s Binlog Phase”
Phase 1: Configuration Check Phase..
检查了 MHA 的配置信息，并再次判断了 master 的可用性。
Phase 2: Dead Master Shutdown Phase..
宕机的 master 处理阶段，包括摘除 VIP，执行 shutdown_script 中定义的脚本。
Phase 3: Master Recovery Phase..
Phase 3.1: Getting Latest Slaves Phase..
判断哪个 slave 拥有最新的 relay log（通过比较 show slave status 中的 Master_Log_File, Read_Master_Log_Pos 位置），
哪个 slave 拥有最旧的 relay log
Phase 3.2: Saving Dead Master’s Binlog Phase..
根据上面得到的 slave 的最新位置信息，将差异的二进制日志保存到 MHA Manager 的指定目录下。
如果在第一步骤中，判断了 MHA Manager 到 master 的 ssh 不可用，则会跳过这个阶段。
Phase 3.3: Determining New Master Phase..
选择新的 master
Phase 3.3: New Master Diff Log Generation Phase..
将差异的 relay log 和 master 差异日志 scp 到新的 master 上。
Phase 3.4: Master Log Apply Phase..
首先，等待 slave 上已有的 relay log 都应用完。
其次，通过 apply_diff_relay_logs 应用差异的 relay log，及差异的 binlog。
应用完毕后，得到新的 master binlog 的文件和位置，其它 slave 可根据该文件和位置来建立主从复制关系。
第三，执行 master_ip_failover 脚本，执行如下操作
1> 将新主的 read_only 设置为 0
2> 启动 vip
Phase 4: Slaves Recovery Phase
Phase 4.1: Starting Parallel Slave Diff Log Generation Phase
为 slave 获取差异的 relay log
因为 192.168.244.30 拥有最新的 relay log，所以也没必要获取差异的 relay log
Phase 4.2: Starting Parallel Slave Log Apply Phase
开始 slave 的恢复阶段
1> 将差异的 relay log 和 master 差异日志 scp 到 slave 上。
2> 应用差异日志。
3> 清除原来的复制关系，并再次执行 change master 命令建立新的主从同步。
如果有多个 slave，则该恢复过程是并行的。
Phase 5: New master cleanup phase
从 MHA 的配置文件中剔除 server1 的配置信息
最后，生成 Failover Report 并发送告警邮件。
更多详情见请继续阅读下一页的精彩内容 ：http://www.linuxidc.com/Linux/2017-05/144249p2.htm
手动 Failover
与自动 Failover 相对应的是手动 Failover，即当 master 发生故障时，通过手动执行脚本来进行故障切换。
命令如下：
# masterha_master_switch –master_state=dead –conf=/etc/masterha/app1.cnf –dead_master_host=192.168.244.10 –dead_master_port=3306 –new_master_host=192.168.244.30 –new_master_port=3306 –ignore_last_failover
输出日志信息如下：
--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:44:20 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:44:20 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:44:20 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:44:20 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:44:20 2017 - [info] Starting master failover.
Wed May 24 19:44:20 2017 - [info]
Wed May 24 19:44:20 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:44:20 2017 - [info]
Wed May 24 19:44:21 2017 - [info] GTID failover mode = 0
Wed May 24 19:44:21 2017 - [info] Dead Servers:
Wed May 24 19:44:21 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:21 2017 - [info] Checking master reachability via MySQL(double check)...
Wed May 24 19:44:21 2017 - [info] ok.
Wed May 24 19:44:21 2017 - [info] Alive Servers:
Wed May 24 19:44:21 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Wed May 24 19:44:21 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:21 2017 - [info] Alive Slaves:
Wed May 24 19:44:21 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:21 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:21 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:21 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:21 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Master 192.168.244.10(192.168.244.10:3306) is dead. Proceed? (yes/NO): yes
Wed May 24 19:44:23 2017 - [info] Starting Non-GTID based failover.
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:23 2017 - [info] ** Phase 1: Configuration Check Phase completed.
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:23 2017 - [info] * Phase 2: Dead Master Shutdown Phase..
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:24 2017 - [info] HealthCheck: SSH to 192.168.244.10 is reachable.
Wed May 24 19:44:24 2017 - [info] Forcing shutdown so that applications never connect to the current master..
Wed May 24 19:44:24 2017 - [info] Executing master IP deactivation script:
Wed May 24 19:44:24 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.
10 --orig_master_port=3306 --command=stopssh --ssh_user=root Disabling the VIP an old master: 192.168.244.10
SIOCSIFFLAGS: Cannot assign requested address
Wed May 24 19:44:24 2017 - [info] done.
Wed May 24 19:44:24 2017 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Wed May 24 19:44:24 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3: Master Recovery Phase..
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000002:120
Wed May 24 19:44:24 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):
Wed May 24 19:44:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000002:120
Wed May 24 19:44:24 2017 - [info] Oldest slaves:
Wed May 24 19:44:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] Fetching dead master's binary logs..
Wed May 24 19:44:24 2017 - [info] Executing command on the dead master 192.168.244.10(192.168.244.10:3306): save_binary_logs --comman
d=save --start_file=mysql-bin.000002 --start_pos=120 --binlog_dir=/var/lib/mysql --output_file=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 Creating /tmp if not exists.. ok.
Concat binary/relay logs from mysql-bin.000002 pos 120 to mysql-bin.000002 EOF into /tmp/saved_master_binlog_from_192.168.244.10_330
6_20170524194420.binlog .. Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 120.. ok.
Dumping effective binlog data from /var/lib/mysql/mysql-bin.000002 position 120 to tail(143).. ok.
Binlog Checksum enabled
Concat succeeded.
saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00
Wed May 24 19:44:24 2017 - [info] scp from root@192.168.244.10:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlo
g to local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:25 2017 - [info] HealthCheck: SSH to 192.168.244.20 is reachable.
Wed May 24 19:44:25 2017 - [info] HealthCheck: SSH to 192.168.244.30 is reachable.
Wed May 24 19:44:25 2017 - [info]
Wed May 24 19:44:25 2017 - [info] * Phase 3.3: Determining New Master Phase..
Wed May 24 19:44:25 2017 - [info]
Wed May 24 19:44:25 2017 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Wed May 24 19:44:25 2017 - [info] All slaves received relay logs to the same position. No need to resync each other.
Wed May 24 19:44:25 2017 - [info] 192.168.244.30 can be new master.
Wed May 24 19:44:25 2017 - [info] New master is 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:25 2017 - [info] Starting master failover..
Wed May 24 19:44:25 2017 - [info]
From:
192.168.244.10(192.168.244.10:3306) (current master)
+--192.168.244.20(192.168.244.20:3306)
+--192.168.244.30(192.168.244.30:3306)
To:
192.168.244.30(192.168.244.30:3306) (new master)
+--192.168.244.20(192.168.244.20:3306)
Starting master switch from 192.168.244.10(192.168.244.10:3306) to 192.168.244.30(192.168.244.30:3306)? (yes/NO): yes
Wed May 24 19:44:32 2017 - [info] New master decided manually is 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:32 2017 - [info]
Wed May 24 19:44:32 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Wed May 24 19:44:32 2017 - [info]
Wed May 24 19:44:32 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Wed May 24 19:44:32 2017 - [info] Sending binlog..
saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00
Wed May 24 19:44:33 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog to
root@192.168.244.30:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 3.4: Master Log Apply Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Wed May 24 19:44:33 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..
Wed May 24 19:44:33 2017 - [info] Generating diffs succeeded.
Wed May 24 19:44:33 2017 - [info] Waiting until all relay logs are applied.
Wed May 24 19:44:33 2017 - [info] done.
Wed May 24 19:44:33 2017 - [info] Getting slave status..
Wed May 24 19:44:33 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000002:120
). No need to recover from Exec_Master_Log_Pos.Wed May 24 19:44:33 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..
Wed May 24 19:44:33 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.16
8.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170524194420 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxxWed May 24 19:44:33 2017 - [info]
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog on 192.168.244.3
0:3306. This may take long time...Applying log files succeeded.
Wed May 24 19:44:33 2017 - [info] All relay logs were successfully applied.
Wed May 24 19:44:33 2017 - [info] Getting new master's binlog name and position..
Wed May 24 19:44:33 2017 - [info] mysql-bin.000001:1429
Wed May 24 19:44:33 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_
HOST='192.168.244.30', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=1429, MASTER_USER='repl', MASTER_PASSWORD='xxx';Wed May 24 19:44:33 2017 - [info] Executing master IP activate script:
Wed May 24 19:44:33 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.
10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.30 --new_master_ip=192.168.244.30 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123' Set read_only=0 on the new master.
Enabling the VIP 192.168.244.188 on the new master: 192.168.244.30
Wed May 24 19:44:33 2017 - [info] OK.
Wed May 24 19:44:33 2017 - [info] ** Finished master recovery successfully.
Wed May 24 19:44:33 2017 - [info] * Phase 3: Master Recovery Phase completed.
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 4: Slaves Recovery Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] -- Slave diff file generation on host 192.168.244.20(192.168.244.20:3306) started, pid: 1598. Check
tmp log /masterha/app1/192.168.244.20_3306_20170524194420.log if it takes time..Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] Log messages from 192.168.244.20 ...
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:33 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Wed May 24 19:44:34 2017 - [info] End of log messages from 192.168.244.20.
Wed May 24 19:44:34 2017 - [info] -- 192.168.244.20(192.168.244.20:3306) has the latest relay log events.
Wed May 24 19:44:34 2017 - [info] Generating relay diff files from the latest slave succeeded.
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] -- Slave recovery on host 192.168.244.20(192.168.244.20:3306) started, pid: 1600. Check tmp log /ma
sterha/app1/192.168.244.20_3306_20170524194420.log if it takes time..saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] Log messages from 192.168.244.20 ...
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:34 2017 - [info] Sending binlog..
Wed May 24 19:44:35 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog to
root@192.168.244.20:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:35 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..
Wed May 24 19:44:35 2017 - [info] Generating diffs succeeded.
Wed May 24 19:44:35 2017 - [info] Waiting until all relay logs are applied.
Wed May 24 19:44:35 2017 - [info] done.
Wed May 24 19:44:35 2017 - [info] Getting slave status..
Wed May 24 19:44:35 2017 - [info] This slave(192.168.244.20)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000002:120
). No need to recover from Exec_Master_Log_Pos.Wed May 24 19:44:35 2017 - [info] Connecting to the target slave host 192.168.244.20, running recover script..
Wed May 24 19:44:35 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.16
8.244.20 --slave_ip=192.168.244.20 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170524194420 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxxWed May 24 19:44:35 2017 - [info]
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog on 192.168.244.2
0:3306. This may take long time...Applying log files succeeded.
Wed May 24 19:44:35 2017 - [info] All relay logs were successfully applied.
Wed May 24 19:44:35 2017 - [info] Resetting slave 192.168.244.20(192.168.244.20:3306) and starting replication from the new master 1
92.168.244.30(192.168.244.30:3306)..Wed May 24 19:44:35 2017 - [info] Executed CHANGE MASTER.
Wed May 24 19:44:35 2017 - [info] Slave started.
Wed May 24 19:44:35 2017 - [info] End of log messages from 192.168.244.20.
Wed May 24 19:44:35 2017 - [info] -- Slave recovery on host 192.168.244.20(192.168.244.20:3306) succeeded.
Wed May 24 19:44:35 2017 - [info] All new slave servers recovered successfully.
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] * Phase 5: New master cleanup phase..
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] Resetting slave info on the new master..
Wed May 24 19:44:35 2017 - [info] 192.168.244.30: Resetting slave info succeeded.
Wed May 24 19:44:35 2017 - [info] Master failover to 192.168.244.30(192.168.244.30:3306) completed successfully.
Wed May 24 19:44:35 2017 - [info]
----- Failover Report -----
app1: MySQL Master failover 192.168.244.10(192.168.244.10:3306) to 192.168.244.30(192.168.244.30:3306) succeeded
Master 192.168.244.10(192.168.244.10:3306) is down!
Check MHA Manager logs at node4 for details.
Started manual(interactive) failover.
Invalidated master IP address on 192.168.244.10(192.168.244.10:3306)
The latest slave 192.168.244.20(192.168.244.20:3306) has all relay logs for recovery.
Selected 192.168.244.30(192.168.244.30:3306) as a new master.
192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded.
192.168.244.30(192.168.244.30:3306): OK: Activated master IP address.
192.168.244.20(192.168.244.20:3306): This host has the latest relay log events.
Generating relay diff files from the latest slave succeeded.
192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.30(192.168.244.30:3
306)192.168.244.30(192.168.244.30:3306): Resetting slave info succeeded.
Master failover to 192.168.244.30(192.168.244.30:3306) completed successfully.
Wed May 24 19:44:35 2017 - [info] Sending mail..
Unknown option: conf在切换的过程中，会有两次确认操作。
通过日志的输出，可以看出，手动 Failover 的切换逻辑和自动 Failover 的切换逻辑基本一致。
在上面的命令中，显示指定了 –new_master_host 参数，如果，没有显示指定该参数的话，则默认新主为 192.168.244.20，因为在 /etc/masterha/app1.cnf 中将主机设置为 candidate_master=1。
事实上，如果 master alive 的话，是不允许切换的。
在默认情况下，如果 MHA 检测到两次切换的时间小于 8 小时，则不允许进行 Failover，这个时候，需指定 –ignore_last_failover 参数
# masterha_master_switch --master_state=dead --conf=/etc/masterha/app1.cnf --dead_master_host=192.168.244.10 --dead_master_port=3306
--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:26:24 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:26:24 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:26:24 2017 - [info] Starting master failover.
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:24 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:26 2017 - [info] GTID failover mode = 0
Wed May 24 19:26:26 2017 - [info] Dead Servers:
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/MasterFailover.pm, ln187] None of server is dead. Stop failover.
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/ManagerUtil.pm, ln177] Got ERROR: at /usr/local/bin/masterha_master_sw
itch line 53.[root@node4 ~]# masterha_master_switch --master_state=dead --conf=/etc/masterha/app1.cnf --dead_master_host=192.168.244.10 --dead_mas
ter_port=3306--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:29:23 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:29:23 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:29:23 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:29:23 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:29:23 2017 - [info] Starting master failover.
Wed May 24 19:29:23 2017 - [info]
Wed May 24 19:29:23 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:29:23 2017 - [info]
Wed May 24 19:29:24 2017 - [info] GTID failover mode = 0
Wed May 24 19:29:24 2017 - [info] Dead Servers:
Wed May 24 19:29:24 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:29:24 2017 - [info] Checking master reachability via MySQL(double check)...
Wed May 24 19:29:24 2017 - [info] ok.
Wed May 24 19:29:24 2017 - [info] Alive Servers:
Wed May 24 19:29:24 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Wed May 24 19:29:24 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:29:24 2017 - [info] Alive Slaves:
Wed May 24 19:29:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:29:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:29:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:29:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log
-bin:enabledWed May 24 19:29:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Master 192.168.244.10(192.168.244.10:3306) is dead. Proceed? (yes/NO): yes
Wed May 24 19:29:46 2017 - [error][/usr/local/share/perl5/MHA/MasterFailover.pm, ln309] Last failover was done at 2017/05/24 16:04:54
. Current time is too early to do failover again. If you want to do failover, manually remove /masterha/app1/app1.failover.complete and run this script again.Wed May 24 19:29:46 2017 - [error][/usr/local/share/perl5/MHA/ManagerUtil.pm, ln177] Got ERROR: at /usr/local/bin/masterha_master_sw
itch line 53.后面附上之前提到的测试结果不理想的两种方案
方案一：
模拟步骤如下：
1. master 上创建测试表
mysql> use sbtest;
Database changed
mysql> create table sbtest.t1(id int primary key,col1 varchar(10),col2 varchar(10),col3 varchar(10),col4 varchar(10),col5 varchar(10),col6 varchar(10),col7 varchar(10),col8 varchar(10),col9 varchar(10),col10 varchar(10));
Query OK, 0 rows affected (0.33 sec)2. 关闭 Candicate master 和 Slave 的主从复制。
mysql> stop slave;
Query OK, 0 rows affected (0.03 sec)3. 在 master 上生成测试数据
创建存储过程
delimiter //
create procedure p1()
begin
declare v1 int default 0;
while v1 <=700000 do
insert into sbtest.t1 values(v1,'aaaaaaaaaa','bbbbbbbbbb','cccccccccc','dddddddddd','eeeeeeeeee','ffffffffff','gggggggggg','hhhhhhhhhh','iiiiiiiiii','jjjjjjjjjj');
set v1=v1+1;
if v1 %1000 =0 then
commit;
end if;
end while;
end//
delimiter ;执行存储过程
mysql> call p1;共执行了两次，生成了 500M 左右的 binlog
[root@node1 ~]# ll -h /var/lib/mysql/mysql-bin.000046
-rw-rw---- 1 mysql mysql 502M Apr 24 15:18 /var/lib/mysql/mysql-bin.000045. 开启 Candicate master 和 Slave 的主从复制并 kill 掉 master 的 mysqld 进程，模拟主库发生故障，进行自动 failover 操作
在这里，我写了个脚本来实现开启 slave 复制并 kill 掉 master mysqld 进程的功能
# vim monitor_slave.py
#!/usr/bin/Python
# coding=utf-8
import MySQLdb
import subprocess
import time
class CheckSlaveStatus:
def __init__(self, host):
self.conn = MySQLdb.connect(host, "monitor", "monitor123")
self.cursor = self.conn.cursor()
self.cursor.execute("start slave")
def get_slave_status(self):
self.cursor.execute("show slave status")
slave_status_result = self.cursor.fetchone()
slave_io_running, slave_sql_running = slave_status_result[10], slave_status_result[11]
return [slave_io_running, slave_sql_running]
def quit(self):
try:
self.conn.commit()
self.conn.close()
except Exception as e:
print e
def main():
check_host = ['192.168.244.30', '192.168.244.20']
check_slave_status_30 = CheckSlaveStatus(check_host[0])
check_slave_status_20 = CheckSlaveStatus(check_host[1])
for check_slave_status in [check_slave_status_30, check_slave_status_20]:
print "Begin to check slave status"
while True:
slave_status = check_slave_status.get_slave_status()
print slave_status
if slave_status == ['Yes', 'Yes']:
time.sleep(5)
break
time.sleep(10)
print "Begin to kill master mysqld"
command_line="ps -ef |grep mysqld |grep -v grep |awk'{print $2}'|xargs kill -9"
p = subprocess.Popen(command_line, stdout=subprocess.PIPE, shell=True)
p.communicate()
check_slave_status_30.quit()
check_slave_status_20.quit()
print "Finished"
if __name__ == '__main__':
main()执行该脚本
6. 查看 MHA 的切换日志
Sun May 21 09:46:56 2017 - [warning] Got error on MySQL select ping: 2006 (MySQL server has gone away)
Sun May 21 09:46:56 2017 - [info] Executing secondary network check script: /usr/local/bin/masterha_secondary_check -s 192.168.244.20 -s 192.168.244.30 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --master_user=monitor --masteConnection timed out during banner exchange
Sun May 21 09:47:08 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun May 21 09:47:08 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:08 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:57 2017 - [warning] Connection failed 2 time(s)..
Sun May 21 09:46:58 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:58 2017 - [warning] Connection failed 3 time(s)..
Sun May 21 09:46:59 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:59 2017 - [warning] Connection failed 4 time(s)..
Monitoring server 192.168.244.20 is reachable, Master is not reachable from 192.168.244.20. OK.
Sun May 21 09:47:01 2017 - [warning] HealthCheck: SSH to 192.168.244.10 is NOT reachable.
Monitoring server 192.168.244.30 is reachable, Master is not reachable from 192.168.244.30. OK.
Sun May 21 09:47:07 2017 - [info] Master is not reachable from all other monitoring servers. Failover should start.
Sun May 21 09:47:07 2017 - [warning] Master is not reachable from health checker!
Sun May 21 09:47:07 2017 - [warning] Master 192.168.244.10(192.168.244.10:3306) is not reachable!
Sun May 21 09:47:07 2017 - [warning] SSH is NOT reachable.
Sun May 21 09:47:07 2017 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/masterha/app1.cnf again, and trying to connect to all servers to check server status..
Sun May 21 09:47:07 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun May 21 09:47:07 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:07 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:08 2017 - [info] GTID failover mode = 0
Sun May 21 09:47:08 2017 - [info] Dead Servers:
Sun May 21 09:47:08 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Alive Servers:
Sun May 21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:08 2017 - [info] Alive Slaves:
Sun May 21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Checking slave configurations..
Sun May 21 09:47:08 2017 - [info] Checking replication filtering settings..
Sun May 21 09:47:08 2017 - [info] Replication filtering check ok.
Sun May 21 09:47:08 2017 - [info] Master is down!
Sun May 21 09:47:08 2017 - [info] Terminating monitoring script.
Sun May 21 09:47:08 2017 - [info] Got exit code 20 (Master dead).
Sun May 21 09:47:08 2017 - [info] MHA::MasterFailover version 0.56.
Sun May 21 09:47:08 2017 - [info] Starting master failover.
Sun May 21 09:47:08 2017 - [info]
Sun May 21 09:47:08 2017 - [info] * Phase 1: Configuration Check Phase..
Sun May 21 09:47:08 2017 - [info]
Sun May 21 09:47:09 2017 - [info] GTID failover mode = 0
Sun May 21 09:47:09 2017 - [info] Dead Servers:
Sun May 21 09:47:09 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Checking master reachability via MySQL(double check)...
Sun May 21 09:47:09 2017 - [info] ok.
Sun May 21 09:47:09 2017 - [info] Alive Servers:
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:09 2017 - [info] Alive Slaves:
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Starting Non-GTID based failover.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] ** Phase 1: Configuration Check Phase completed.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] Forcing shutdown so that applications never connect to the current master..
Sun May 21 09:47:09 2017 - [info] Executing master IP deactivation script:
Sun May 21 09:47:09 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --command=stop
Disabling the VIP an old master: 192.168.244.10
Sun May 21 09:47:09 2017 - [info] done.
Sun May 21 09:47:09 2017 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Sun May 21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3: Master Recovery Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000001:37651149
Sun May 21 09:47:09 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:09 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000001:35083093
Sun May 21 09:47:09 2017 - [info] Oldest slaves:
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [warning] Dead Master is not SSH reachable. Could not save it's binlogs. Transactions that were not sent to the latest slave (Read_Master_Log_Pos to the tail of the dead master's binlog) were lost.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.3: Determining New Master Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Sun May 21 09:47:10 2017 - [info] HealthCheck: SSH to 192.168.244.20 is reachable.
Sun May 21 09:47:10 2017 - [info] Checking whether 192.168.244.20 has relay logs from the oldest position..
Sun May 21 09:47:10 2017 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --workdir=/tmp --timestamp=20170521094708 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/ :
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000004
Fast relay log position search succeeded.
Target relay log file/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.
Target relay log FOUND!
Sun May 21 09:47:11 2017 - [info] OK. 192.168.244.20 has all relay logs.
Sun May 21 09:47:11 2017 - [info] HealthCheck: SSH to 192.168.244.30 is reachable.
Sun May 21 09:47:13 2017 - [info] Searching new master from slaves..
Sun May 21 09:47:13 2017 - [info] Candidate masters from the configuration file:
Sun May 21 09:47:13 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:13 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:13 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:13 2017 - [info] Non-candidate masters:
Sun May 21 09:47:13 2017 - [info] Searching from candidate_master slaves which have received the latest relay log events..
Sun May 21 09:47:13 2017 - [info] New master is 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:13 2017 - [info] Starting master failover..
Sun May 21 09:47:13 2017 - [info]
From:
192.168.244.10(192.168.244.10:3306) (current master)
+--192.168.244.20(192.168.244.20:3306)
+--192.168.244.30(192.168.244.30:3306)
To:
192.168.244.20(192.168.244.20:3306) (new master)
+--192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] * Phase 3.4: Master Log Apply Phase..
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Sun May 21 09:47:13 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..
Sun May 21 09:47:13 2017 - [info] This server has all relay logs. Waiting all logs to be applied..
Sun May 21 09:47:56 2017 - [info] done.
Sun May 21 09:47:56 2017 - [info] All relay logs were successfully applied.
Sun May 21 09:47:56 2017 - [info] Getting new master's binlog name and position..
Sun May 21 09:47:56 2017 - [info] mysql-bin.000010:166054508
Sun May 21 09:47:56 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.244.20', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000010', MASTER_LOG_POS=166054508, MASTER_USER='repl', MASTER_PASSWORD='xxx';
Sun May 21 09:47:56 2017 - [info] Executing master IP activate script:
Sun May 21 09:47:56 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.20 --new_master_ip=192.168.244.20 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123'
Set read_only=0 on the new master.
Enabling the VIP 192.168.244.188 on the new master: 192.168.244.20
Sun May 21 09:47:59 2017 - [info] OK.
Sun May 21 09:47:59 2017 - [info] ** Finished master recovery successfully.
Sun May 21 09:47:59 2017 - [info] * Phase 3: Master Recovery Phase completed.
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] * Phase 4: Slaves Recovery Phase..
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] -- Slave diff file generation on host 192.168.244.30(192.168.244.30:3306) started, pid: 3606. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:47:59 2017 - [info] Server 192.168.244.30 received relay logs up to: mysql-bin.000001:35083093
Sun May 21 09:47:59 2017 - [info] Need to get diffs from the latest slave(192.168.244.20) up to: mysql-bin.000001:37651149 (using the latest slave's relay logs)
Sun May 21 09:47:59 2017 - [info] Connecting to the latest slave host 192.168.244.20, generating diff relay log files..
Sun May 21 09:47:59 2017 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.244.30 --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --diff_file_readtolatest=/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/
Sun May 21 09:48:04 2017 - [info]
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000004
Fast relay log position search succeeded.
Target relay log file/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.
Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083256 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog ..
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /var/lib/mysql/mysqld-relay-bin.000004 position 35083256 to tail(37651312).. ok.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Generating diff relay log succeeded. Saved at /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog .
scp node2:/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog to root@192.168.244.30(22) succeeded.
Sun May 21 09:48:04 2017 - [info] Generating diff files succeeded.
Sun May 21 09:48:04 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 09:48:04 2017 - [info] -- Slave diff log generation on host 192.168.244.30(192.168.244.30:3306) succeeded.
Sun May 21 09:48:04 2017 - [info] Generating relay diff files from the latest slave succeeded.
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) started, pid: 3613. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:04 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..
Sun May 21 09:48:04 2017 - [info] Generating diffs succeeded.
Sun May 21 09:48:04 2017 - [info] Waiting until all relay logs are applied.
Sun May 21 09:48:04 2017 - [info] done.
Sun May 21 09:48:04 2017 - [info] Getting slave status..
Sun May 21 09:48:04 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos(mysql-bin.000001:35083010) does not equal to Read_Master_Log_Pos(mysql-bin.000001:35083093). It is likely that relay log was cut during transaction. Need to recover from Exec_Master_Log_Pos.
Sun May 21 09:48:04 2017 - [info] Saving local relay logs from exec pos to read pos on 192.168.244.30: from mysqld-relay-bin.000004:35083173 to the end of the relay log..
Sun May 21 09:48:04 2017 - [info] Executing command : save_binary_logs --command=save --start_file=mysqld-relay-bin.000004 --start_pos=35083173 --output_file=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --binlog_dir=/var/lib/mysql/
Sun May 21 09:48:05 2017 - [info]
Creating /tmp if not exists.. ok.
Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083173 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog ..
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /var/lib/mysql/mysqld-relay-bin.000004 position 35083173 to tail(35083256).. ok.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Sun May 21 09:48:05 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..
Sun May 21 09:48:05 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Sun May 21 09:48:12 2017 - [info]
Concat all apply files to /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog ..
Copying the first binlog file /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog to /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog.. ok.
Dumping binlog head events (rotate events), skipping format description events from /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog.. Binlog Checksum enabled
Binlog Checksum enabled
dumped up to pos 283. ok.
/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog has effective binlog events from pos 283.
Dumping effective binlog data from /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog position 283 to tail(2568339).. ok.
Concat succeeded.
All apply target binary logs are concatinated at /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog .
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog on 192.168.244.30:3306. This may take long time...
Applying log files succeeded.
Sun May 21 09:48:12 2017 - [info] All relay logs were successfully applied.
Sun May 21 09:48:12 2017 - [info] Resetting slave 192.168.244.30(192.168.244.30:3306) and starting replication from the new master 192.168.244.20(192.168.244.20:3306)..
Sun May 21 09:48:12 2017 - [info] Executed CHANGE MASTER.
Sun May 21 09:48:12 2017 - [info] Slave started.
Sun May 21 09:48:12 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 09:48:12 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) succeeded.
Sun May 21 09:48:12 2017 - [info] All new slave servers recovered successfully.
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] * Phase 5: New master cleanup phase..
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] Resetting slave info on the new master..
Sun May 21 09:48:12 2017 - [info] 192.168.244.20: Resetting slave info succeeded.
Sun May 21 09:48:12 2017 - [info] Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 09:48:12 2017 - [info] Deleted server1 entry from /etc/masterha/app1.cnf .
Sun May 21 09:48:12 2017 - [info]
----- Failover Report -----
app1: MySQL Master failover 192.168.244.10(192.168.244.10:3306) to 192.168.244.20(192.168.244.20:3306) succeeded
Master 192.168.244.10(192.168.244.10:3306) is down!
Check MHA Manager logs at node4:/masterha/app1/manager.log for details.
Started automated(non-interactive) failover.
Invalidated master IP address on 192.168.244.10(192.168.244.10:3306)
The latest slave 192.168.244.20(192.168.244.20:3306) has all relay logs for recovery.
Selected 192.168.244.20(192.168.244.20:3306) as a new master.
192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded.
192.168.244.20(192.168.244.20:3306): OK: Activated master IP address.
192.168.244.30(192.168.244.30:3306): Generating differential relay logs up to 192.168.244.20(192.168.244.20:3306)succeeded.
Generating relay diff files from the latest slave succeeded.
192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.20(192.168.244.20:3306)
192.168.244.20(192.168.244.20:3306): Resetting slave info succeeded.
Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 09:48:12 2017 - [info] Sending mail..
Unknown option: conf方案二
对 Candicate master 上和 Slave 上的网卡进行带宽限制
Candicate master
[root@node2 ~]# /sbin/tc qdisc add dev eth0 root tbf rate 50kbit latency 50ms burst 15kb
Slave
/sbin/tc qdisc add dev eth0 root tbf rate 80kbit latency 50ms burst 15kb
注意：Candicate master 的网卡限制在 50kbit，slave 的网卡限制在 80kbit，
要确保 Candicate master 的小于 slave 的，这样才能模拟出 Candicate master 上 relay log 的位置小于 slave 上 relay log 的位置。
关于如何确认网卡的速率控制到多大合适，
可通过压测，测试 master 的吞吐量，
以及结合如下方法，测试主机之间的传输速率来确定网卡合适的速率。
[root@node1 ~]# dd if=/dev/zero of=hello.txt bs=100M count=1
[root@node1 ~]# time scp hello.txt 192.168.244.20:/tmp/
hello.txt 100% 100MB 2.6MB/s 00:39
参考
《深入浅出 MySQL》PDF 下载见 http://www.linuxidc.com/Linux/2016-05/130922.htm
本文永久更新链接地址 ：http://www.linuxidc.com/Linux/2017-05/144249.htm
集群信息
角色 IP 地址 ServerID 类型
Master 192.168.244.10 1 写入
Candicate master 192.168.244.20 2 读
Slave 192.168.244.30 3 读
Monitor host 192.168.244.40 监控集群组
MHA 具体的搭建步骤和原理，可参考另外一篇文章：
MySQL 高可用方案 MHA 的部署和原理 http://www.linuxidc.com/Linux/2017-05/144086.htm
自动 Failover
为了通过 MHA 的日志清晰判断 MHA 自动 Failover 的实现原理，需模拟如下场景：
当主库发生故障时，master 中还有一部分 binlog 日志没有传输到 Candicate master 和 Slave 上，且 Slave 上的二进制日志多于 Candicate master 上。
尝试了几种方案，总算如愿以偿。
方案一：
1. 关闭 Candicate master 和 Slave 的主从复制。
2. 通过存储过程生成测试数据
3. 开启 Candicate master 和 Slave 的主从复制并 kill 掉 master 的 mysqld 进程，模拟主库发生故障，进行自动 failover 操作
为此，还特意写了个脚本，可惜的是，效果并不理想，在自动 Failover 的过程中，显示 MHA Manager 到 master 的“SSH is NOT reachable”。
方案二：
通过 tc 命令对 Candicate master 和 Slave 的网卡分别设置不同的传输速率，确保发送到 Candicate master 的日志量小于 Slave 上的。
很可惜，效果同方案一一样。
方案三：
在主从复制中，直接关闭 master 的 mysqld 数据库。
但是，通过这样方式，并不会实现 Slave 上的二进制日志多于 Candicate master 的效果。
方案四：
通过截取 relay log，在关掉 slave 的情况下，修改 master.info 和 relay-log.info 的位置点来人为制造 Candicate master 的日志量小于 Slave 的。
事后想想，其实这样的方法就等同于先关闭 Candicate master 的主从复制，再在 master 上执行一段操作，再关闭 slave 上的主从复制，再在 master 上执行一段操作。
这样不就实现了 master 的 binlog > slave 的 relay log > Candicate master 的 relay log。
方案四总算如愿以偿
下面通过方案四看看 MHA 的实现原理
1. 创建测试表，并插入测试数据
2. 分别查看 master 上 binlog 的内容，slave 上 relay log 的内容
Master
mysql> show binlog events;
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
| mysql-bin.000001 | 4 | Format_desc | 1 | 120 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysql-bin.000001 | 120 | Query | 1 | 238 | create table sbtest.b(id int,name varchar(10)) |
| mysql-bin.000001 | 238 | Query | 1 | 315 | BEGIN |
| mysql-bin.000001 | 315 | Query | 1 | 421 | insert into sbtest.b values(1,'a') |
| mysql-bin.000001 | 421 | Xid | 1 | 452 | COMMIT /* xid=102 */ |
| mysql-bin.000001 | 452 | Query | 1 | 529 | BEGIN |
| mysql-bin.000001 | 529 | Query | 1 | 635 | insert into sbtest.b values(2,'b') |
| mysql-bin.000001 | 635 | Xid | 1 | 666 | COMMIT /* xid=103 */ |
| mysql-bin.000001 | 666 | Query | 1 | 743 | BEGIN |
| mysql-bin.000001 | 743 | Query | 1 | 849 | insert into sbtest.b values(3,'c') |
| mysql-bin.000001 | 849 | Xid | 1 | 880 | COMMIT /* xid=104 */ |
| mysql-bin.000001 | 880 | Query | 1 | 957 | BEGIN |
| mysql-bin.000001 | 957 | Query | 1 | 1063 | insert into sbtest.b values(4,'d') |
| mysql-bin.000001 | 1063 | Xid | 1 | 1094 | COMMIT /* xid=105 */ |
| mysql-bin.000001 | 1094 | Query | 1 | 1171 | BEGIN |
| mysql-bin.000001 | 1171 | Query | 1 | 1277 | insert into sbtest.b values(5,'e') |
| mysql-bin.000001 | 1277 | Xid | 1 | 1308 | COMMIT /* xid=106 */ |
+------------------+------+-------------+-----------+-------------+------------------------------------------------+
17 rows in set (0.01 sec)Slave
mysql> show relaylog events in 'mysqld-relay-bin.000002';
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
| mysqld-relay-bin.000002 | 4 | Format_desc | 2 | 120 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysqld-relay-bin.000002 | 120 | Rotate | 1 | 0 | mysql-bin.000001;pos=120 |
| mysqld-relay-bin.000002 | 167 | Format_desc | 1 | 0 | Server ver: 5.6.31-log, Binlog ver: 4 |
| mysqld-relay-bin.000002 | 283 | Query | 1 | 238 | create table sbtest.b(id int,name varchar(10)) |
| mysqld-relay-bin.000002 | 401 | Query | 1 | 315 | BEGIN |
| mysqld-relay-bin.000002 | 478 | Query | 1 | 421 | insert into sbtest.b values(1,'a') |
| mysqld-relay-bin.000002 | 584 | Xid | 1 | 452 | COMMIT /* xid=102 */ |
| mysqld-relay-bin.000002 | 615 | Query | 1 | 529 | BEGIN |
| mysqld-relay-bin.000002 | 692 | Query | 1 | 635 | insert into sbtest.b values(2,'b') |
| mysqld-relay-bin.000002 | 798 | Xid | 1 | 666 | COMMIT /* xid=103 */ |
| mysqld-relay-bin.000002 | 829 | Query | 1 | 743 | BEGIN |
| mysqld-relay-bin.000002 | 906 | Query | 1 | 849 | insert into sbtest.b values(3,'c') |
| mysqld-relay-bin.000002 | 1012 | Xid | 1 | 880 | COMMIT /* xid=104 */ |
| mysqld-relay-bin.000002 | 1043 | Query | 1 | 957 | BEGIN |
| mysqld-relay-bin.000002 | 1120 | Query | 1 | 1063 | insert into sbtest.b values(4,'d') |
| mysqld-relay-bin.000002 | 1226 | Xid | 1 | 1094 | COMMIT /* xid=105 */ |
| mysqld-relay-bin.000002 | 1257 | Query | 1 | 1171 | BEGIN |
| mysqld-relay-bin.000002 | 1334 | Query | 1 | 1277 | insert into sbtest.b values(5,'e') |
| mysqld-relay-bin.000002 | 1440 | Xid | 1 | 1308 | COMMIT /* xid=106 */ |
+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+
19 rows in set (0.00 sec)通过对比 master 中的 binlog event，可以看到 show relaylog events 中的 End_log_pos 实际上指的是对应的二进制事件在 binlog 的位置。
再来查看 Candicate master 中对应的 relay log 的内容
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170524 17:16:37 server id 2 end_log_pos 120 CRC32 0x4faba9ae Start: binlog v 4, server v 5.6.31-log created 170524 17:16:37
BINLOG 'dU8lWQ8CAAAAdAAAAHgAAABAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAa6p
q08=
'/*!*/;
# at 120
#700101 8:00:00 server id 1 end_log_pos 0 CRC32 0x74c6d70c Rotate to mysql-bin.000001 pos: 120
# at 167
#170524 17:15:49 server id 1 end_log_pos 0 CRC32 0xed2672eb Start: binlog v 4, server v 5.6.31-log created 170524 17:15:49
BINLOG 'RU8lWQ8BAAAAdAAAAAAAAAAAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAety
Ju0=
'/*!*/;
# at 283
#170524 17:17:20 server id 1 end_log_pos 238 CRC32 0xdd48c118 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617440/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table sbtest.b(id int,name varchar(10))
/*!*/;
# at 401
#170524 17:17:27 server id 1 end_log_pos 315 CRC32 0xae393750 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617447/*!*/;
BEGIN
/*!*/;
# at 478
#170524 17:17:27 server id 1 end_log_pos 421 CRC32 0x28a781ae Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617447/*!*/;
insert into sbtest.b values(1,'a')
/*!*/;
# at 584
#170524 17:17:27 server id 1 end_log_pos 452 CRC32 0x680f1bfe Xid = 29
COMMIT/*!*/;
# at 615
#170524 17:17:33 server id 1 end_log_pos 529 CRC32 0x6a1aae7e Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617453/*!*/;
BEGIN
/*!*/;
# at 692
#170524 17:17:33 server id 1 end_log_pos 635 CRC32 0x117786ca Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617453/*!*/;
insert into sbtest.b values(2,'b')
/*!*/;
# at 798
#170524 17:17:33 server id 1 end_log_pos 666 CRC32 0xa8400ec6 Xid = 30
COMMIT/*!*/;
# at 829
#170524 17:17:38 server id 1 end_log_pos 743 CRC32 0x24f9a1d2 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617458/*!*/;
BEGIN
/*!*/;
# at 906
#170524 17:17:38 server id 1 end_log_pos 849 CRC32 0x56fa9e89 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617458/*!*/;
insert into sbtest.b values(3,'c')
/*!*/;
# at 1012
#170524 17:17:38 server id 1 end_log_pos 880 CRC32 0x2ac656d4 Xid = 31
COMMIT/*!*/;
# at 1043
#170524 17:17:44 server id 1 end_log_pos 957 CRC32 0x73a903bf Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617464/*!*/;
BEGIN
/*!*/;
# at 1120
#170524 17:17:44 server id 1 end_log_pos 1063 CRC32 0x171b9b27 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617464/*!*/;
insert into sbtest.b values(4,'d')
/*!*/;
# at 1226
#170524 17:17:44 server id 1 end_log_pos 1094 CRC32 0x47d6fe57 Xid = 32
COMMIT/*!*/;
# at 1257
#170524 17:17:49 server id 1 end_log_pos 1171 CRC32 0x2d37da37 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617469/*!*/;
BEGIN
/*!*/;
# at 1334
#170524 17:17:49 server id 1 end_log_pos 1277 CRC32 0xd2201fa2 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1495617469/*!*/;
insert into sbtest.b values(5,'e')
/*!*/;
# at 1440
#170524 17:17:49 server id 1 end_log_pos 1308 CRC32 0xac1b464e Xid = 33
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;mysql 中 binlog 有个有意思的地方是，位置点其实是也是字节的大小。
譬如，上面这个 relay log 中，最后一个位点是# at 1440，算上最后一个 commit 操作需占用 31 个字节，所以整个文件的大小是 1471，与实际大小吻合。
[root@node2 mysql]# ll mysqld-relay-bin.000002
-rw-rw---- 1 mysql mysql 1471 May 24 17:17 mysqld-relay-bin.0000023. 通过 show slave status 查看 io thread 和 sql thread 的位置信息
待会儿需要修改上面 Master_Log_File,Read_Master_Log_Pos,Relay_Log_File,Relay_Log_Pos,Relay_Master_Log_File,Exec_Master_Log_Pos 的值。
虽然这几个参数的值与 master.info 和 relay-log.info 文件是相对应的，
但通过修改 master.info 和 relay-log.info 的值，并重启 slave，并不会将上述几个参数值修改。
上述几个参数是保存到内存中的，唯一可行的方案是首先关闭 slave 实例，再修改 master.info 和 relay-log.info 文件，然后重新启动 mysql 实例。
4. 关闭 Candicate master 实例，剪裁 relay log，修改 master.info 和 relay-log.info 文件。
关闭实例
[root@node2 mysql]# service mysqld stop
剪裁 relay log
这里，写了个 Python 脚本实现该功能
在上述脚本 size1 中，615 对应的是 insert into sbtest.b values(1,’a’) 这条记录
[root@node2 mysql]# python 1.py
[root@node2 mysql]# mv tmp_relay_bin mysqld-relay-bin.000002
修改 master.info 的内容
主要是修改第三行
23
mysql-bin.000001
1308修改为
23
mysql-bin.000001
452修改 relay-log.info 的内容
原文件如下：
7
./mysqld-relay-bin.000002
1471
mysql-bin.000001
1308
0
0
1修改为：
7
./mysqld-relay-bin.000002
615
mysql-bin.000001
452
0
0
1启动 slave，注意，配置文件中必须设置 skip-slave-start，不然它自动开启主从复制。
[root@node2 mysql]# service mysqld start
5. 对于 slave，同样如此处理，只不过 relay log 的位置点要靠后些
#!/usr/bin/python
f1 = open('mysqld-relay-bin.000002','r')
f2 = open('tmp_relay_bin','w+')
size1=f1.read(1043)
f2.write(size1)
f1.seek(1471)
size2=f1.read()
f2.write(size2)
f1.close()
f2.close()1043 对应的是 insert into sbtest.b values(3,’c’) 这条记录
修改 master.info 的内容
23
mysql-bin.000001
880修改 relay-log.info 的内容
7
./mysqld-relay-bin.000002
1043
mysql-bin.000001
880
0
0
1 6. 开启 MHA 监控
# nohup masterha_manager –conf=/etc/masterha/app1.cnf –remove_dead_master_conf –ignore_last_failover < /dev/null >
/masterha/app1/manager.log 2>&1 &
# masterha_check_status –conf=/etc/masterha/app1.cnf
app1 (pid:1615) is running(0:PING_OK), master:192.168.244.107. 关闭 master 实例
# service mysqld stop
8. 查看 MHA 切换日志，了解整个切换过程。
该日志的时间点与上面 relay log 的时间点并不吻合，原因在于这个反复测试了很多次。
从上面的日志输出可以看出整个 MHA 的切换过程
首先，MHA Manager 检测到 master 不可用，则会通过另外两个 slave 检查 master 的可用性。一共检测 4 次。
同时判断 MHA Manager 到 master 的 ssh 可用性。
ssh 可用性的判断结果影响后后续切换中的“Phase 3.2: Saving Dead Master’s Binlog Phase”
Phase 1: Configuration Check Phase..
检查了 MHA 的配置信息，并再次判断了 master 的可用性。
Phase 2: Dead Master Shutdown Phase..
宕机的 master 处理阶段，包括摘除 VIP，执行 shutdown_script 中定义的脚本。
Phase 3: Master Recovery Phase..
Phase 3.1: Getting Latest Slaves Phase..
判断哪个 slave 拥有最新的 relay log（通过比较 show slave status 中的 Master_Log_File, Read_Master_Log_Pos 位置），
哪个 slave 拥有最旧的 relay log
Phase 3.2: Saving Dead Master’s Binlog Phase..
根据上面得到的 slave 的最新位置信息，将差异的二进制日志保存到 MHA Manager 的指定目录下。
如果在第一步骤中，判断了 MHA Manager 到 master 的 ssh 不可用，则会跳过这个阶段。
Phase 3.3: Determining New Master Phase..
选择新的 master
Phase 3.3: New Master Diff Log Generation Phase..
将差异的 relay log 和 master 差异日志 scp 到新的 master 上。
Phase 3.4: Master Log Apply Phase..
首先，等待 slave 上已有的 relay log 都应用完。
其次，通过 apply_diff_relay_logs 应用差异的 relay log，及差异的 binlog。
应用完毕后，得到新的 master binlog 的文件和位置，其它 slave 可根据该文件和位置来建立主从复制关系。
第三，执行 master_ip_failover 脚本，执行如下操作
1> 将新主的 read_only 设置为 0
2> 启动 vip
Phase 4: Slaves Recovery Phase
Phase 4.1: Starting Parallel Slave Diff Log Generation Phase
为 slave 获取差异的 relay log
因为 192.168.244.30 拥有最新的 relay log，所以也没必要获取差异的 relay log
Phase 4.2: Starting Parallel Slave Log Apply Phase
开始 slave 的恢复阶段
1> 将差异的 relay log 和 master 差异日志 scp 到 slave 上。
2> 应用差异日志。
3> 清除原来的复制关系，并再次执行 change master 命令建立新的主从同步。
如果有多个 slave，则该恢复过程是并行的。
Phase 5: New master cleanup phase
从 MHA 的配置文件中剔除 server1 的配置信息
最后，生成 Failover Report 并发送告警邮件。
更多详情见请继续阅读下一页的精彩内容 ：http://www.linuxidc.com/Linux/2017-05/144249p2.htm
正文完
星哥说事-微信公众号
