mysql 夯死排查_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，主库和从库时这样同步的：

在主节点：执行 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–