目录
文/温国兵
一 引子
研发反应，有台从库和主库不同步。由于业务读操作是针对从库的，数据不同步必定会带来数据的不一致，业务获取的结果会受影响，所以这个问题必须尽快解决。
登上服务器，查看 MySQL 的从库状态，并没有任何报错信息。刷新从库状态，发现状态没有任何变化，Exec_Master_Log_Pos 卡住不动。
二 故障分析
为了安全起见，此文略去 MySQL 版本以及其他可能会带来安全问题的信息。
接下来逐步分析问题。
首先查看从库状态：
mysql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
Slave_IO_State: Queueing master event to the relay log
Master_Host: masterIP
Master_User: replUser
Master_Port: masterPort
Connect_Retry: 60
Master_Log_File: binlog.000296
Read_Master_Log_Pos: 364027786
Relay_Log_File: relaylog.000002
Relay_Log_Pos: 250
Relay_Master_Log_File: binlog.000283
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:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 594374863
Relay_Log_Space: 13803486573
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: 256219
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: masterID
1 row in set (0.00 sec)
此时的 Slave_IO_State 为 Queueing master event to the relay log，而不是正常状态下的 Waiting for master to send event。刷新多次，状态没有任何变化，Exec_Master_Log_Pos 不变，从而导致 Seconds_Behind_Master 一直不变。
接下来查看 PROCESSLIST 状态：
mysql> SHOW FULL PROCESSLIST;
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
| 51378 | system user | | NULL | Connect | 1121183 | Waiting for master to send event | NULL |
| 88917 | system user | | NULL | Connect | 245327 | Reading event from the relay log | NULL |
| 106029 | userA | xxx.xxx.xxx.xxx:14057 | NULL | Sleep | 14504 | | NULL |
| 106109 | userA | xxx.xxx.xxx.xxx:15077 | databaseA | Sleep | 79 | | NULL |
| 106110 | userA | xxx.xxx.xxx.xxx:15081 | databaseA | Sleep | 13000 | | NULL |
| 106116 | userB | xxx.xxx.xxx.xxx:15096 | databaseA | Sleep | 357 | | NULL |
| 106117 | userB | xxx.xxx.xxx.xxx:15097 | NULL | Sleep | 12964 | | NULL |
| 106119 | root | localhost | NULL | Query | 0 | NULL | SHOW FULL PROCESSLIST |
| 106126 | userB | xxx.xxx.xxx.xxx:15173 | NULL | Sleep | 12856 | | NULL |
| 106127 | userB | xxx.xxx.xxx.xxx:15180 | databaseA | Sleep | 12849 | | NULL |
| 106766 | userA | xxx.xxx.xxx.xxx:17960 | databaseA | Sleep | 64 | | NULL |
+--------+-------------+------------------+--------------------+---------+---------+---------------+------------------+
11 rows in set (0.00 sec)
从以上的结果来看，没有任何异常。
既然从上述信息中得不到任何对排查问题有帮助的信息，那么我们可以试着分析 MySQL 的 binlog，看 Pos 为 594374863 的点发生了什么操作。
分析日志我们可以使用 mysqlbinlog 命令，指定 start-position 为夯住的那个点，并重定向到文件。
/usr/local/mysql/bin/mysqlbinlog --no-defaults -v --start-position="594374863" \
binlog.000283 > /XXX/binlog.sql
查看输出结果，发现端倪了，以下是摘抄的部分结果：
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150814 17:43:15 server id 21 end_log_pos 107 Start: binlog v 4, server v x.x.xx-log created 150814 17:43:15
BINLOG '
M7jNVQ8VAAAAZwAAAGsAAAAAAAQANS41LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==
'/*!*/;
# at 594374863
#150814 18:09:36 server id 21 end_log_pos 594374945 Query thread_id=210702841 exec_time=43 error_code=0
SET TIMESTAMP=1439546976/*!*/;
SET @@session.pseudo_thread_id=210702841/*!*/;
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=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 594374945
# at 594375036
# at 594376047
# at 594377085
# at 594378123
# at 594379152
# at 594380187
# at 594381165
# at 594382194
# at 594383223
# at 594384252
# at 594385269
# at 594386307
# at 594387282
# at 594388299
# at 594389265
# at 594390270
# at 594391299
# at 594392310
# at 594393327
# at 594394344
# at 594395340
# at 594396336
# at 594397332
从以上输出中，我们可以知道，从夯住的那个点开始，binlog 记录的信息就出现了异常，可以推测在主库有大操作。另外，针对出现问题库，查看主库和从库的表数量，发现从库的表数量多于主库，有几个临时表出现。可以推测的，主库有删表的操作，从库同步夯住，导致同步异常，主库删表的操作还没来得及同步到从库。
经过和研发沟通，确认了两点。第一，确实有大操作，程序有大量的批量插入，而且是用的 LOAD DATA LOCAL INFILE；第二，主库确实有删表的操作，这几张表都是临时表。
三 故障解决
既然问题找到了，那解决办法自然就有了。既然从库的表多于主库，而且这几张表是临时数据，我们可以过滤掉对这几张表的同步操作。具体思路如下：在主库备份临时表（虽然研发说数据不重要，但还是以防万一，DBA 还是谨慎为好），然后通知研发临时切走从库的流量，修改配置文件，指定 replicate-ignore-table 参数，重启 MySQL。
接下来就是具体的解决步骤，首先备份数据。备份时不加 –master-data 参数和 –single-transaction。究其原因，–master-data 禁用 –lock-tables 参数，在和 –single-transaction 一起使用时会禁用 –lock-all-tables。在备份开始时，会获取全局 read lock。 –single-transaction 参数设置默认级别为 REPEATABLE READ，
并且在开始备份时执行 START TRANSACTION。在备份期间， 其他连接不能执行如下语句：ALTER TABLE、CREATE TABLE、DROP TABLE、RENAME TABLE、TRUNCATE TABLE。MySQL 同步夯住，如果加了上述参数，mysqldump 也会夯住。mysqldump 会 FLUSH TABLES、LOCK TABLES，如果有 –master-data 参数，会导致 Waiting for table flush。同样，有 –single-transaction 参数，仍然会导致 Waiting for table flush。另外，还可以看到 Waiting for table metadata lock，此时做了 DROP TABLE 的操作。此时可以停掉 MySQL 同步来避免这个问题。
为了保险起见，我们在主库加大 expire_logs_days 参数，避免 binlog 丢失。
mysql> SHOW VARIABLES LIKE '%expire%';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| expire_logs_days | 3 |
+------------------+-------+
1 row in set (0.00 sec)
mysql> SET GLOBAL expire_logs_days=5;
Query OK, 0 rows affected (0.00 sec)
mysql> SHOW VARIABLES LIKE '%expire%';
+------------------+-------+
| Variable_name | Value |
+------------------+-------+
| expire_logs_days | 5 |
+------------------+-------+
1 row in set (0.00 sec)
接着修改从库的配置文件：
vim /xxx/xxxx/xxx/my.cnf
在 mysqld 后，加入如下配置：
然后重启 MySQL：
/xxx/xxx/xxx/xxx/mysqld restart
登录 MySQL 从库，查看从库状态，并定时刷新状态，我们可以看到的是，Exec_Master_Log_Pos 在递增，Seconds_Behind_Master 在递减，证明问题已经解决了。
mysql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: masterIP
Master_User: replUser
Master_Port: masterPort
Connect_Retry: 60
Master_Log_File: binlog.000319
Read_Master_Log_Pos: 985656691
Relay_Log_File: relaylog.000004
Relay_Log_Pos: 709043542
Relay_Master_Log_File: binlog.000284
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: databaseA.tableA,databaseA.tableB,databaseA.tableC,databaseA.tableD
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 709043399
Relay_Log_Space: 38579192969
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: 258490
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: masterID
1 row in set (0.00 sec)
需要注意的是，待同步完成后，需要把从库配置文件中增加的 replicate-ignore-table参数注释，并重启 MySQL。
四 原理探讨
在主库运行 LOAD DATA LOCAL INFILE，主库和从库时这样同步的：
- 在主节点：
- 执行 LOAD DATA LOCAL INFILE；
- 拷贝使用的整个文本文件内容到二进制日志；
- 添加 LOAD DATA LOCAL INFILE 到最新的二进制日志。
- 复制所有主库的二进制日志到从库的中继日志；
- 在从节点：
- 检查中继日志中的文本文件；
- 从多个中继日志文件中读取所有的块；
- 文本文件存放在 /tmp 文件夹中；
- 从中继日志中读取 LOAD DATA LOCAL INFILE；
- 在 SQL 线程中执行 LOAD DATA LOCAL INFILE。
在从节点执行的 1-4 步骤中，IO 线程会呈现 Reading event from the relay log 状态，持续地为下一个 LOAD DATA LOCAL INFILE 命令提取 CSV 行。此时从库会持续落后，一旦从库落后时间较长，会导致 SQL 线程阻塞，呈现 Queueing master event to the relay log 状态，从而复制夯住。
五 小结
这样的故障，归根结底还是研发写的程序还有优化的余地。大批量的数据插入，这在 MySQL 中是不推荐使用的。我们可以这样：第一，一条 SQL 语句插入多条数据；第二，在事务中进行插入处理；第三，分批插入，在程序中设置 auto_commit 为 0，分批插入完成后，手动 COMMIT；第四，需要使用 LOAD DATA LOCAL INFILE 时，设置 sync_binlog 为 1。
–EOF–