MySQL 复制夯住排查以及原理探讨
一、引子
研发反应，有台从库和主库不同步。由于业务读操作是针对从库的，数据不同步必定会带来数据的不一致，业务获取的结果会受影响，所以这个问题必须尽快解决。
登上服务器，查看 MySQL 的从库状态，并没有任何报错信息。刷新从库状态，发现状态没有任何变化，Exec_Master_Log_Pos 卡住不动。
二、故障分析
为了安全起见，此文略去 MySQL 版本以及其他可能会带来安全问题的信息，接下来逐步分析问题。
首先查看从库状态
mysql> SHOW SLAVE STATUS \G ***********************[i][b][/i] 1. row [/b]************************* 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查看输出结果，发现端倪了，以下是摘抄的部分结果：
/[i]!40019 SET @@session.max_insert_delayed_threads=0[/i]/; /[i]!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0[/i]/; DELIMITER /[i]![/i]/; # 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== '/[i]![/i]/; # 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/[i]![/i]/; SET @@session.pseudo_thread_id=210702841/[i]![/i]/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/[i]![/i]/; SET @@session.sql_mode=0/[i]![/i]/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/[i]![/i]/; /[i]!\C utf8 [/i]//[i]![/i]/; SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/[i]![/i]/; SET @@session.lc_time_names=0/[i]![/i]/; SET @@session.collation_database=DEFAULT/[i]![/i]/; BEGIN /[i]![/i]/; # 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 后，加入如下配置：
replicate-ignore-table=databaseA.tableA replicate-ignore-table=databaseA.tableB replicate-ignore-table=databaseA.tableC replicate-ignore-table=databaseA.tableD然后重启 MySQL：
/xxx/xxx/xxx/xxx/mysqld restart登录 MySQL 从库，查看从库状态，并定时刷新状态，我们可以看到的是，Exec_Master_Log_Pos 在递增，Seconds_Behind_Master 在递减，证明问题已经解决了。
mysql> SHOW SLAVE STATUS \G ***********************[i][b][/i] 1. row [/b]************************* 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。[/]
