暂无图片
暂无图片
1
暂无图片
暂无图片
暂无图片
首页 / 【记一次MySQL主从复制延迟问题分析】

【记一次MySQL主从复制延迟问题分析】

原创 张sir 2022-10-19
2073

前言

MySQL数据库的主从延迟问题在生产上还是很经常出现的，从MySQL5.7以后开始出现基于write set的并行复制，主从延迟的问题得到的了大大的缓解，但是由于开发在使用MySQL的过程中，并不了解主从复制的原理，也不会遵循MySQL一些最佳实践，导致主从延迟的问题依然大量存在。本文是生产上处理的一次主从延迟问题。文末总结给出了解决主从延迟的几个关键点。

分析思路

对于主从复制延迟的问题，我的分析思路是这样的：

  1. 通过show slave status确认，延迟binlog的点，主要查看 Relay_Log_File、Relay_Log_Pos，重点关注Relay_Log_Pos是否变化。
  2. 如果Relay_Log_Pos一直不变，说明可能是遇到了大事务。可以解析相关的binlog、relaylog看看对哪个表在操作。
  3. 从binlog/relaylog中找到表名，可以确定这个操作是delete还是update还是insert。
  4. 再去相应的主库的慢日志中，根据对应的时间点，找是否有相关慢查询。此时可以确定该SQL的具体内容，看看是否需要优化SQL。
  5. 如果第2步查到的Relay_Log_Pos一直在变，说明备库一直在回放事务，那么可以看看操作系统的io情况是不是给力，是否卡其了并行。

问题分析

1、登录备库查看数据库的复制情况，主从延迟已经达到了2269592s，且Relay_Log_Pos保持不变，应该是遇到大事务了。

                Connect_Retry: 60
              Master_Log_File: mysql-bin.002211
          Read_Master_Log_Pos: 51704210
               Relay_Log_File: mysqld-relay-bin.006395
                Relay_Log_Pos: 13999474
        Relay_Master_Log_File: mysql-bin.002134                
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
	      Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 2269592    
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error:

2、利用mysqlbinlog解析当前的relaylog找到当前操作的表，确认为对表req_log的delete操作，时间为210422 2:18:07s发起的事务。


# at 13999474
#210422  2:18:07 server id 2  end_log_pos 13999395 CRC32 0x755796e1     Query   thread_id=107738405     exec_time=0     error_code=0
SET TIMESTAMP=1619029087/*!*/;
SET @@session.pseudo_thread_id=107738405/*!*/;
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=2, @@session.auto_increment_offset=2/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 13999559
#210422  2:18:07 server id 2  end_log_pos 13999481 CRC32 0x651ea915     Table_map: `abc`.`req_log` mapped to number 286931
# at 13999645
#210422  2:18:07 server id 2  end_log_pos 14007611 CRC32 0xcd1abf13     Delete_rows: table id 286931
# at 14007775
#210422  2:18:07 server id 2  end_log_pos 14015737 CRC32 0x408739cf     Delete_rows: table id 286931
# at 14015901
#210422  2:18:07 server id 2  end_log_pos 14023927 CRC32 0x855917e7     Delete_rows: table id 286931
# at 14024091
#210422  2:18:07 server id 2  end_log_pos 14032103 CRC32 0x9adfe391     Delete_rows: table id 286931

3、根据表名和对应事务的时间点去主库慢日志，看能否匹配到相关的SQL。找到了一个delete语句。在主库执行了22s。

# Time: 210422  2:18:30
# User@Host: abc[abc] @  [21.123.119.129]  Id: 107738405
# Query_time: 22.972652  Lock_time: 0.000143 Rows_sent: 0  Rows_examined: 6241045 Logical_reads: 0 Physical_reads: 0
SET timestamp=1619029110;
DELETE from req_log
where date(sys_date_time)<=date_sub(curdate(),interval 3 day);

4、看下该delete语句的执行计划是全表扫描。

explain select * from req_log
where date(sys_date_time)<=date_sub(curdate(),interval 3 day);

+----+-------------+---------+------+---------------+------+---------+------+---------+-------------+
| id | select_type | table   | type | possible_keys | key  | key_len | ref  | rows    | Extra       |
+----+-------------+---------+------+---------------+------+---------+------+---------+-------------+
|  1 | SIMPLE      | req_log | ALL  | NULL          | NULL | NULL    | NULL | 4231103 | Using where |
+----+-------------+---------+------+---------------+------+---------+------+---------+-------------+

5、看下表的数据量，从统计信息上看，大概有4百万。

mysql> select table_name,table_rows,data_length/1024/1024/1024 from tables where table_name in ('req_log');
+------------+------------+----------------------------+
| table_name | table_rows | data_length/1024/1024/1024 |
+------------+------------+----------------------------+
| req_log    |    4231227 |             0.876449584961 |
+------------+------------+----------------------------+
``
6、看下这个表是否有索引。没有任何索引。
```language
mysql> show create table req_log\G
*************************** 1. row ***************************
       Table: req_log
Create Table: CREATE TABLE `req_log` (
  `id` varchar(40) DEFAULT NULL,
  `app_id` varchar(8) DEFAULT NULL,
  `res_json_param` text COMMENT '响应的json参数',
  `req_type` varchar(10) DEFAULT NULL COMMENT '请求类型',
  `req_json_param` text COMMENT '请求的json参数',
  `sys_date_time` datetime DEFAULT NULL COMMENT '系统时间',
  `attachments_path` varchar(100) DEFAULT NULL COMMENT '附件路径',
  `result_type` varchar(10) DEFAULT NULL COMMENT '结果类型',
  `api_name` varchar(255) DEFAULT NULL COMMENT '调用接口名称',
  `ask_resp_time` varchar(255) DEFAULT NULL,
  `tts_resp_time` varchar(255) DEFAULT NULL,
  `rtp_resp_time` varchar(255) DEFAULT NULL,
  `srp_resp_time` varchar(255) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8
/*!50100 PARTITION BY RANGE (MONTH(sys_date_time))
(PARTITION p1 VALUES LESS THAN (2) ENGINE = InnoDB,
 PARTITION p2 VALUES LESS THAN (3) ENGINE = InnoDB,
 PARTITION p3 VALUES LESS THAN (4) ENGINE = InnoDB,
 PARTITION p4 VALUES LESS THAN (5) ENGINE = InnoDB,
 PARTITION p5 VALUES LESS THAN (6) ENGINE = InnoDB,
 PARTITION p6 VALUES LESS THAN (7) ENGINE = InnoDB,
 PARTITION p7 VALUES LESS THAN (8) ENGINE = InnoDB,
 PARTITION p8 VALUES LESS THAN (9) ENGINE = InnoDB,
 PARTITION p9 VALUES LESS THAN (10) ENGINE = InnoDB,
 PARTITION p10 VALUES LESS THAN (11) ENGINE = InnoDB,
 PARTITION p11 VALUES LESS THAN (12) ENGINE = InnoDB,
 PARTITION p12 VALUES LESS THAN (13) ENGINE = InnoDB) */
1 row in set (0.00 sec)

7、经过以上分析，发下出现问题的是一个delete语句，而且被清理的表上没有索引，也没有主键。那为什么我们要关注索引和主键呢，这里讲一下，mysql的binlog在row模式下的记录的格式，对于一个delete或者update语句：delete from big_table where id<10;binlog里实际上记录的是如下的形式，也就是说如果主库清理掉10条记录，日志就会记录10条delete，而且这个delete后面的where条件带上了所有的字段值。如果表没有索引或者主键，在主库执行一次的全表扫描，备库就要执行10次的全表扫描。这对于批量的清理或者更新就很恐怖了，在主库执行1w次的清理，你可能感觉不太慢，那么备库在重放的时候可能麻烦了。

### DELETE FROM `test`.`big_table`
### WHERE
###   @1=10 /* INT meta=0 nullable=0 is_null=0 */
###   @2=3 /* INT meta=0 nullable=1 is_null=0 */
###   @3='d3d9446802a44259755d38e6d163e820' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @4=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @7=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @8=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @9=NULL /* INT meta=0 nullable=1 is_null=1 */
### DELETE FROM `test`.`big_table`
### WHERE
###   @1=11 /* INT meta=0 nullable=0 is_null=0 */
###   @2=4 /* INT meta=0 nullable=1 is_null=0 */
###   @3='6512bd43d9caa6e02c990b0a82652dca' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @4=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @7=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @8=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @9=NULL /* INT meta=0 nullable=1 is_null=1 */
### DELETE FROM `test`.`big_table`
### WHERE
###   @1=13 /* INT meta=0 nullable=0 is_null=0 */
###   @2=6 /* INT meta=0 nullable=1 is_null=0 */
###   @3='c51ce410c124a10e0db5e4b97fc2af39' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @4=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @7=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @8=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @9=NULL /* INT meta=0 nullable=1 is_null=1 */
### DELETE FROM `test`.`big_table`
### WHERE
###   @1=14 /* INT meta=0 nullable=0 is_null=0 */
###   @2=0 /* INT meta=0 nullable=1 is_null=0 */
###   @3='aab3238922bcc25a6f606eb525ffdc56' /* VARSTRING(128) meta=128 nullable=1 is_null=0 */
###   @4=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @5=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @6=NULL /* VARSTRING(40) meta=40 nullable=1 is_null=1 */
###   @7=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @8=NULL /* INT meta=0 nullable=1 is_null=1 */
###   @9=NULL /* INT meta=0 nullable=1 is_null=1 */

8、基于以上的分析，对于这种情况，我们建议表上都加上主键，没有业务字段可以做主键，可以添加自增列。再不济就加个索引，也比啥也没有强。我们的这个问题由于延迟实在是太久了，即使现在加上了主键或者索引，短期内也无法同步到备库。我们建议先在表上加索引或主键，然后再重做备机，这样备库可以马上就用上索引。

总结

1、对于MySQL种使用Innodb的表来说，一定要加上主键，这也是很多大公司的硬性要求。
2、对于批量操作，建议分批提交，减少事务量。
3、无法添加主键的，建议添加选择性好的唯一索引或者普通索引。
4、如果以上均暂时无法满足，可以尝试调整参数slave_rows_search_algorithms，这个参数指定了备库在扫描表的是时候的算法，默认是TABLE_SCAN,INDEX_SCAN，可以调整成HASH_SCAN,TABLE_SCAN。
5、如果对于大量的insert操作导致的备库延迟，可以尝试临时调整innodb_flush_log_at_trx_commit和sync_binlog设置成非1，提高io的利用率。
6、以上操作均在生产环境做过实施，安全性还是可以保证的。
7、文章https://www.modb.pro/db/47411?utm_source=index_ai分析了一些源码级别的解释，大家可以看看。

墨力计划故障处理
最后修改时间：2023-03-22 13:48:51
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

评论