MySQL 复制夯住一例排查以及原理探讨

目录

---

• 目录
• 一 引子
• 二 故障分析
• 三 故障解决
• 四 原理探讨
• 五 小结

文/温国兵

一 引子

---

研发反应，有台从库和主库不同步。由于业务读操作是针对从库的，数据不同步必定会带来数据的不一致，业务获取的结果会受影响，所以这个问题必须尽快解决。

登上服务器，查看 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 后，加入如下配置：

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
*************************** 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，主库和从库时这样同步的：

• 在主节点：
  1. 执行 LOAD DATA LOCAL INFILE；
  2. 拷贝使用的整个文本文件内容到二进制日志；
  3. 添加 LOAD DATA LOCAL INFILE 到最新的二进制日志。
• 复制所有主库的二进制日志到从库的中继日志；
• 在从节点：
  1. 检查中继日志中的文本文件；
  2. 从多个中继日志文件中读取所有的块；
  3. 文本文件存放在 /tmp 文件夹中；
  4. 从中继日志中读取 LOAD DATA LOCAL INFILE；
  5. 在 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–