意想不到的MySQL复制延迟原因

导读

线上有个MySQL实例,存在严重的复制延迟问题,原因出乎意料。

线上有个MySQL 5.7版本的实例,从服务器延迟了3万多秒,而且延迟看起来好像还在加剧。

MySQL版本

Server version:     5.7.18-log MySQL Community Server (GPL)

看下延迟状况

yejr@imysql.com:mysql3306.sock : (none) > show slave status\G
              Master_Log_File: mysql-bin.013225
          Read_Master_Log_Pos: 1059111551
        Relay_Master_Log_File: mysql-bin.013161
          Exec_Master_Log_Pos: 773131396
                  Master_UUID: e7c35a95-ffb1-11e6-9620-90e2babb5b90

我们看到,binlog文件落后了64个,相当的夸张。

MySQL 5.7不是已经实现并行复制了吗,怎么还会延迟这么厉害?

先检查系统负载。
先看I/O子系统负载,没看到这方面存在瓶颈。

再看mysqld进程的CPU消耗。

可以看到mysqld进程的CPU消耗长时间超过100%。

再检查MySQL复制现场,确认了几个频繁更新的表都有主键,以及必要的索引,相应的DML操作,也几乎都是基于主键或唯一索引条件执行的,排除无主键、无合理索引方面的因素。

最后只能祭出perf top神器了。

perf top -p `pidof mysqld`

看到perf top最后的报告是这样的

Samples: 107K of event 'cycles', Event count (approx.): 29813195000                                                                                                                              
Overhead  Shared Object        Symbol                                                                                                                                                            
  56.19%  mysqld               [.] bitmap_get_next_set                                                                                                                                           
  16.18%  mysqld               [.] build_template_field                                                                                                                                          
   4.61%  mysqld               [.] ha_innopart::try_semi_consistent_read                                                                                                                         
   4.44%  mysqld               [.] dict_index_copy_types                                                                                                                                         
   4.16%  libc-2.12.so         [.] __memset_sse2                                                                                                                                                 
   2.92%  mysqld               [.] ha_innobase::build_template

我们看到, bitmap_get_next_set 这个函数调用占到了 56.19%,非常高,其次是 build_template_field 函数,占了 16.18%。

经过检查MySQL源码并请教MySQL内核开发专家,最后确认这两个函数跟启用表分区有关系。查询下当前实例有多少个表分区:

yejr@imysql.com:mysql3306.sock : (none) > select count(*) from partitions where partition_name is not null;
+----------+
| count(*) |
+----------+
|    32128 |
+----------+
1 row in set (11.92 sec)

我勒个去,竟然有3万多个表分区,难怪上面那两个函数调用那么高。

这个业务数据库几个大表采用每天一个分区方案,而且把直到当年年底所有分区也都给提前创建好了,所以才会有这么多。

不过,虽然有这么多表分区,在master服务器上却不存在这个瓶颈,看起来是在主从复制以及大量表分区的综合因素下才有这个瓶颈,最终导致主从复制延迟越来越严重。

知道问题所在,解决起来就简单了。把直到下个月底前,其余还用不到的表分区全部删除,之后约只剩下1.6万个分区。重启slave线程,问题解决,主从复制延迟很快就消失了。

最后,这个问题对应的bug(#85352)在此,已在5.6.38、5.7.20、8.0.3等版本修复了。

FAQ系列 | table id问题导致主从复制失败

0、导读

主从复制环境中,IO、SQL线程都很正常,也没设置过滤规则,但数据就是无法复制到slave上,什么原因?

1、问题描述

事实上,这个案例发生已经有一阵子了,一直拖到现在我才整理。

发现一个主从环境中,slave上的io_thread、sql_thread状态均正常,relay log也正常接收来自master的event,但slave上却无法正常应用这些event,个别表数据没有复制过来。而且slave上的binlog也没有记录这些表上的操作。

2、原因分析

接到现场后,第一反应是是先检查是否设置了ignore/do规则,发现并不是这个原因引起的。

我自己手动测试创建了个新的测试表,写了几条数据,发现在slave上这个表能被创建,但写入的测试数据仍旧无法复制过来。这说明,slave上的复制并不是完全失效的,只是有特殊情形下才会失效。

结合上面的问题,想到了可能是因为binlog format以及事务隔离级别等原因导致失效的,于是做了下面的尝试。

//首先修改事务隔离级别为RR(此前是RC),尽可能保证主从数据一致性

root@imysql [mydb]> set session transaction isolation level repeatable read;

//测试写入2条数据

root@imysql [mydb]> insert into z select 5,5;

root@imysql [mydb]> insert into z select 6,6;

经过观察,这2条数据不可以复制到slave上。

//修改binlog format为statement(此前是row),再写入2条数据

root@imysql [mydb]> set session binlog_format=’statement’;

root@imysql [mydb]> insert into z select 7,7;

root@imysql [mydb]> insert into z select 8,8;

经过观察,这2条数据则可以复制到slave上。

现在至少表面上看起来,是由于binlog format+事务隔离级别综合因素引起的,所以我们来对比下不同binlog format下的binlog有什么区别吧。

tableid1
这些日志中,前两条是row模式下的日志,后两条则是statement模式下的。我们注意到红框中内容是:table_id: 24874588093,正是由于这个原因导致了slave无法正常复制数据。

正常情况下,row模式下的binlog event应该是这样的:

tableid2
在上面的日志中,我们看到的是:table_id: 108,这种情况下就可以正常复制了。

现在问题很明确了,就是由于binlog中table id异常导致无法复制。那么,到底什么原因导致table id出现异常呢。

3、案例建议

搜索了一些资料,发现也有别人遇到同样的问题。我就不多啰嗦了,大家可以看下方参考文章详细了解下。简言之,发生这中问题的原因,主要是因为table cache不够了,导致要频繁打开、关闭table,导致table id急剧增长,因而导致主从数据复制失败。

解决办法有几个:

  1. 加大 table_cache_size,或者 table_open_cache 值,以及 table_definition_cache 选项。一般设置不低于总table数量的1.5倍,更严谨的话,要看 Open_tables 和 Opened_tables 这两个status值。Open_tables 表示当前正被打开的table数量,而 Opened_tables 表示历史上反复打开table的总次数。如果 Opened_tables 值特别高,表明 table cache 很可能不够用所致。
  2. 择机重启主库实例,让table id的值再次从0开始计数。
  3. 临时解决方案:把binlog format改成statement,并且把事务隔离级别改成RR,尽量避免数据不一致的风险。

本文参考:

1. 杨奇龙《【MySQL】再说MySQL中的 table_id 》,http://blog.itpub.net/22664653/viewspace-1158547/

2. yuyue2014《MySQL table_id原理及风险分析》,http://www.cnblogs.com/yuyue2014/p/3721172.html

关于MySQL的方方面面大家想了解什么,可以直接留言回复,我会从中选择一些热门话题进行分享。 同时希望大家多多转发,多一些阅读量是老叶继续努力分享的绝佳助力,谢谢大家 :)

最后打个广告,运维圈人士专属铁观音茶叶微店上线了,访问:http://yejinrong.com 直达

FAQ系列 | 从MySQL 5.6到5.7复制错误解决

0、导读

在MySQL 5.7下采用多源复制方式,从5.6复制数据过来,会有问题吗?

1、问题描述

Q群里有位朋友想尝鲜5.7的多源复制,于是用MySQL 5.7版本作为slave,把MySQL 5.6作为master,想要将数据进行汇总,发现此路不通。

他在my.cnf中设置了2个选项,开启并发复制:

slave_parallel_type    = LOGICAL_CLOCK

slave_parallel_workers = 4

启动复制线程后,结果在错误日志中不断有类似下面的信息:

Transaction is tagged with inconsistent logical timestamps: sequence_number (823267087) <= last_committed (1301275374434324336)

执行 SHOW SLAVE STATUS\G 查看状态:

*************************** 1. row ***************************

Slave_IO_State: Waiting for master to send event

Last_Errno: 1756

Last_Error: … The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details).

Last_SQL_Errno: 1756

Last_SQL_Error: … The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details).

Last_IO_Error_Timestamp:

Last_SQL_Error_Timestamp: 160523 18:49:05

*************************** 2. row ***************************

Slave_IO_State: Waiting for master to send event

Last_Errno: 1756

Last_Error: … The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details).

Skip_Counter: 0

Last_SQL_Errno: 1756

Last_SQL_Error: … The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state. A restart should restore consistency automatically, although using non-transactional storage for data or info tables or DDL queries could lead to problems. In such cases you have to examine your data (see documentation for details).

2、原因分析

上面这些错误提示可以看到,主要原因是:slave端采用了基于 LOGICAL_CLOCK 类型的并行复制,但master端的binlog格式并不支持这种方式,所以slave端无法正确读取binlog并行apply。

3、解决方案

虽然仍旧可以采用MySQL 5.7作为slave,但就无法开启基于 LOGICAL_CLOCK 类型的并行复制了。需要改回传统模式就可以了:

slave_parallel_type    = DATABASE

此外,在MySQL复制方案中,强烈建议不要让主从大版本不一样,很容易出现各种各样的问题。

 

关于MySQL的方方面面大家想了解什么,可以直接留言回复,我会从中选择一些热门话题进行分享。 同时希望大家多多转发,多一些阅读量是老叶继续努力分享的绝佳助力,谢谢大家 :)

最后打个广告,运维圈人士专属铁观音茶叶微店上线了,访问:http://yejinrong.com 直达

FAQ系列 | 列类型被自动修改导致复制失败

0、导读

在复制环境中,有个表的列类型总是被修改,导致复制进程报错停止

1、问题描述

问题发生在朋友的数据库上,做了主从复制,其中某表有一列类型是INT,但是该表上的INSERT事件在BINLOG中却总被记录为MEDIUMINT类型,导致这个事件在SLAVE上执行失败。

相关现场信息见下:

MySQL版本:官方5.5.版本。

表DDL定义:

CREATE TABLE `t` (

`userid` int(10) unsigned NOT NULL DEFAULT 0,

这个表上的INSERT事件在BINLOG中的记录:

### INSERT INTO `imysql`.`t`

### SET

###   @1=207 /* MEDIUMINT meta=0 nullable=0 is_null=0 */

我们看到BINLOG中,这个列类型显示为MEDIUMINT,这个事件在SLAVE上就会报告下面的错误,导致SLAVE无法继续复制:

Column 0 of table ‘imysql.t’ cannot be converted from type ‘mediumint’ to type ‘int(10) unsigned

又是一个看起来很奇葩的案例。

2、原因分析

经过沟通排查,了解到他们的业务模式有点特殊,是从一个旧的空表中复制表结构生成每天日志表,然后再将当天的日志写入该表。也就是大概做法是:

1、创建每天日志表

CREATE TABLE t SELECT t_orig;

2、写入日志

INSERT INTO t SELECT * FROM t_orig;

其实问题就出在每天创建新表的过程中,源表结构像是这样的:

CREATE TABLE `t_orig` (

`userid` mediumint(8) unsigned NOT NULL AUTO_INCREMENT,

从源表复制到新表之后,又执行了ALTER TABLE,把 userid 列类型从 MEDIUMINT 改为 INT,创建存储过程等其他工作。

生成新表后,再写入生成的日志。但是呢,写入日志却又是采用INSERT…SELECT的用法。一般情况下当然没问题,但这个例子中,源表、目标表的 userid 列类型恰好不一样(源是MEDIUMINT,目标是INT),结果导致在 binglog 中记录event时,将 userid 列类型强制转换为 MEDIUMINT 了。这个 INSERT 在 MASTER 端可以正常执行完毕,但却引发了 SLAVE 检测到二者数据类型不一致,写入失败,复制异常中断。

3、问题建议

遇到这种案例也真的是醉了,从源表每天克隆一个新表做法没问题,采用INSERT…SELECT也没问题,但为啥要源表和新表使用不同数据类型呢,直接把源表的也改成INT不就行了吗,只能说某些人懒得不像样了。

4、类似案例

FAQ系列 | 列类型被自动修改导致复制失败

 

关于MySQL的方方面面大家想了解什么,可以直接留言回复,我会从中选择一些热门话题进行分享。 同时希望大家多多转发,多一些阅读量是老叶继续努力分享的绝佳助力,谢谢大家 :)

最后打个广告,运维圈人士专属铁观音茶叶微店上线了,访问:http://yejinrong.com 获得专属优惠

 

FAQ系列 | SLAVE为什么一直不动了

导读

遇到SLAVE延迟很大,binlog apply position一直不动的情况如何排查?

问题描述

收到SLAVE延迟时间一直很大的报警,于是检查一下SLAVE状态(无关状态我给隐去了):

          Slave_IO_State: Waiting for master to send event
         Master_Log_File: mysql-bin.000605
     Read_Master_Log_Pos: 1194
          Relay_Log_File: mysql-relay-bin.003224
           Relay_Log_Pos: 295105
   Relay_Master_Log_File: mysql-bin.000604
        Slave_IO_Running: Yes
       Slave_SQL_Running: Yes
              Last_Errno: 0
              Last_Error: 
     Exec_Master_Log_Pos: 294959
         Relay_Log_Space: 4139172581
   Seconds_Behind_Master: 10905

可以看到,延迟确实很大,而且从多次show slave status的结果来看,发现binlog的position一直不动。

     Read_Master_Log_Pos: 1194
          Relay_Log_File: mysql-relay-bin.003224
           Relay_Log_Pos: 295105
   Relay_Master_Log_File: mysql-bin.000604
     Exec_Master_Log_Pos: 294959
         Relay_Log_Space: 4139172581

从processlist的中也看不出来有什么不对劲的SQL在跑:

******************** 1. row ******************
     Id: 16273070
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 4828912
  State: Waiting for master to send event
   Info: NULL
********************* 2. row *****************
     Id: 16273071
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 9798
  State: Reading event from the relay log
   Info: NULL

在master上查看相应binlog,确认都在干神马事:

[yejr@imysql.com]# mysqlbinlog -vvv --base64-output=decode-rows -j 294959 mysql-bin.000604 | more

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
**# at 294959**
#160204  6:16:30 server id 1  end_log_pos 295029     **Query    thread_id=461151**    **exec_time=2144**    error_code=0
SET TIMESTAMP=1454537790/*!*/;
SET @@session.pseudo_thread_id=461151/*!*/;
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 latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 295029
# at 295085
# at 296040
# at 297047
# at 298056
# at 299068
# at 300104

上面这段内容的几个关键信息:

# at 294959   — binlog起点
thread_id=461151    — master上执行的线程ID
exec_time=2144    — 该事务执行总耗时

再往下看都是一堆的binlog position信息,通过这种方式可读性不强,我们换一种姿势看看:

[yejr@imysql.com (test)]> show binlog events in 'mysql-bin.000604' from 294959 limit 10;
+------------------+--------+-------------+-----------+-------------+----------------------------+
| Log_name         | Pos    | Event_type  | Server_id | End_log_pos | Info                       |
+------------------+--------+-------------+-----------+-------------+----------------------------+
| mysql-bin.000604 | 294959 | Query       |         1 |      295029 | BEGIN                      |
| mysql-bin.000604 | 295029 | Table_map   |         1 |      295085 | table_id: 84 (bacula.File) |
| mysql-bin.000604 | 295085 | Delete_rows |         1 |      296040 | table_id: 84               |
| mysql-bin.000604 | 296040 | Delete_rows |         1 |      297047 | table_id: 84               |
| mysql-bin.000604 | 297047 | Delete_rows |         1 |      298056 | table_id: 84               |
| mysql-bin.000604 | 298056 | Delete_rows |         1 |      299068 | table_id: 84               |
| mysql-bin.000604 | 299068 | Delete_rows |         1 |      300104 | table_id: 84               |
| mysql-bin.000604 | 300104 | Delete_rows |         1 |      301116 | table_id: 84               |
| mysql-bin.000604 | 301116 | Delete_rows |         1 |      302147 | table_id: 84               |
| mysql-bin.000604 | 302147 | Delete_rows |         1 |      303138 | table_id: 84               |

+—————————+————+——————-+—————-+——————-+——————————————+

可以看到,这个事务不干别的,一直在删除数据。
这是一个Bacula备份系统,会每天自动删除一个月前的过期数据。
事实上,这个事务确实非常大,从binlog的294959开始,一直到这个binlog结束4139169218,一直都是在干这事,总共大概有3.85G的binlog要等着apply。

-rw-rw---- 1 mysql mysql 1.1G Feb  3 03:07 mysql-bin.000597
-rw-rw---- 1 mysql mysql 1.1G Feb  3 03:19 mysql-bin.000598
-rw-rw---- 1 mysql mysql 2.1G Feb  3 03:33 mysql-bin.000599
-rw-rw---- 1 mysql mysql 1.4G Feb  3 03:45 mysql-bin.000600
-rw-rw---- 1 mysql mysql 1.8G Feb  3 04:15 mysql-bin.000601
-rw-rw---- 1 mysql mysql 1.3G Feb  3 04:53 mysql-bin.000602
-rw-rw---- 1 mysql mysql 4.5G Feb  4 06:16 mysql-bin.000603
-rw-rw---- 1 mysql mysql 3.9G Feb  4 06:52 mysql-bin.000604
-rw-rw---- 1 mysql mysql 1.2K Feb  4 06:52 mysql-bin.000605

可以看到上面的历史binlog,个别情况下,一个事务里一次性要删除数据量太大了,导致binlog文件远超预设的1G,最大的达到4.5G之多。

怎么解决

由于这是Bacula备份系统内置生成的大事务,除非去修改它的源码,否则没有太好的办法。

对于我们一般的应用而言,最好是攒够一定操作后,就先提交一下事务,比如删除几千条记录后提交一次,而不是像本例这样,一个删除事务消耗了将近3.9G的binlog日质量,这种就非常可怕了。

除了会导致SLAVE看起来一直不动以外,还可能会导致某些数据行(data rows)被长时间锁定不释放,而导致大量行锁等待发生。

 

关于MySQL的方方面面大家想了解什么,可以直接留言回复,我会从中选择一些热门话题进行分享。 同时希望大家多多转发,多一些阅读量是老叶继续努力分享的绝佳助力,谢谢大家 :)

最后打个广告,运维圈人士专属铁观音茶叶微店上线了,访问:http://yejinrong.com 获得专属优惠