一、背景
上周,所负责一个系统遇到MySQL的bug,导致所有从库卡在某一个点无法继续同步主库的更新。具体表现:主库后面挂载的10几个从库都停在同一个点,Relay_Master_Log_File和Exec_Master_Log_Pos一直不停滚动,但SQL却没有被执行,即relay log有被扫描的行为,但却没有被真正执行的行为。
主库环境
MySQL版本:5.1.63
Binlog格式:ROW模式
针对该Case,现梳理并总结如下:
二、排查过程
经历的排查办法包括:
1、怀疑MySQL版本问题,将其中一个从库换成跟主库一样的版本,仍然无法同步 --failed
2、怀疑卡住点的event有问题,因卡住的是MHA的心跳表跟用户数据无关,选择跳过该点,仍然无法正常同步 —failed
3、怀疑主库上binlog格式有问题,从库拉取到本地relay log后,都不认识这种格式导致无法正常执行。但对比主库跟其他5.1版本ROW格式的binlog,均没发现任何异常。
后来,跟MySQL内核组同学一起debug代码发现:是由于table_id太大(已溢出),从库在应用relay log的event时因匹配不到正确的表结构而无法正常应用event。后来通过网上搜索,发现此类问题早就有过此类情况。
三、问题分析
1、table_id 增长特点
- table_id 并不是固定的,它是当表被载入内存(table_definition_cache)时,临时分配的,是一个不断增长的变量。
- 当有新的 table 变更时,在 cache 中没有,就会触发一次 load table def 的操作,此时就会在原先最后一次table_id基础上+1,做为新的 table def 的id,导致 table_id 不断增长
- flush tables,之后对表的更新操作也会触发 table_id 的增长。
- 如果 table def cache 过小,就会出现频繁的换入换出,从而导致 table_id 增长比较快
2、ROW模式下binlog记录的Table_map_event和Row_log_event对应关系
- 测试SQL
mysql> insert into t2 values(1,'a'),(2,'b'),(3,'c');
Query OK, 3 rows affected (0.00 sec)
Records: 3 Duplicates: 0 Warnings: 0
- 对应的binlog日志
BEGIN
/*!*/;
# at 394
# at 480
#171218 0:10:19 server id 1872041750 end_log_pos 480 group_id 14 Table_map: `DB`.`t2` mapped to number 29
#171218 0:10:19 server id 1872041750 end_log_pos 538 group_id 14 Write_rows: table id 29 flags: STMT_END_F exec_time=0
'/*!*/;
### INSERT INTO DB.t2
### SET
### @1=1 /* INT meta=0 nullable=1 is_null=0 */
### @2='a' /* STRING(30) meta=65054 nullable=1 is_null=0 */
### INSERT INTO DB.t2
### SET
### @1=2 /* INT meta=0 nullable=1 is_null=0 */
### @2='b' /* STRING(30) meta=65054 nullable=1 is_null=0 */
### INSERT INTO DB.t2
### SET
### @1=3 /* INT meta=0 nullable=1 is_null=0 */
### @2='c' /* STRING(30) meta=65054 nullable=1 is_null=0 */
# at 538
#171218 0:10:19 server id 1872041750 end_log_pos 573 group_id 14 Xid = 6143 exec_time=0
COMMIT/*!*/;
从以上解析的binlog可以看出,row模式下,DML记录为:TABLE_MAP_EVENT(表结构信息) + ROW_LOG_EVENT(包括WRITE_ROWS_EVENT ,UPDATE_ROWS_EVENT,DELETE_ROWS_EVENT).
为什么一个insert操作在ROW模式下需要分解成两个event:一个Table_map,一个Write_rows?
首先,我们需要了解:ROW模式下,binlog会记录对每条记录的修改。比如上面测试的SQL,虽然只有一条query,但是因为插入3条数据,binlog会记录3条插入记录。
我们想象一下,一个insert如果插入了10000条数据,那么对应的表结构信息是否需要记录10000次?其实是对同一个表的操作,所以这里binlog只是记录了一个Table_map用于记录表结构相关信息,而后面的Write_rows记录了更新数据的行信息。他们之间是通过table_id来联系的。
3、table_id在主从复制中的转变
以5.1为例:
[x@x mysql-5.1]$ grep 'table_id;' sql/table.h
uint table_id; /* table id (from binlog) for opened table */
[x@x mysql-5.1]$ grep 'table_id;' sql/log_event.h
ulong get_table_id() const { return m_table_id; }
ulong m_table_id;
ulong get_table_id() const { return m_table_id; }
ulong m_table_id; /* Table ID */
TABLE_LIST->table_id为uint类型;Table_map_log_event->m_table_id为ulong类型。
从2中binlog日志可以看出:
a、TABLE_MAP_EVENT 阶段,每个event操作的表的相关信息会记录到Table_map中的hash数据结构中,hash结构通过set_table()方法构造,其中hash的key就是表的table_id(ulong型),hash的值就是表的数据结构(包含了表的各种信息,包括数据库名,表名,字段数,字段类型等)。ROW_LOG_EVENT部分通过get_table()方法从hash结构中根据table_id(ulong型)获得对应表的数据结构信息。
b、当主库的binlog传递到从库,每一个log_event都是通过do_apply_event()方法来将relay log中的event应用到本地数据库中。在apply relay log中的event时,do_apply_event()将Table_map阶段ulong型的m_table_id读取出来,然后赋值给RPL_TABLE_LIST结构中的uint型的table_id。(核心问题出现了: 如果binlog 中的table_id 的值大于max(uint)(4294967295),在变量传递时,就会发生截断。)
c、如果hash结构中table_id超过2^32,则b中读取出的table_id已被截断,然后再使用get_table(m_table_id)获取到的ulong型的table_id去匹配,也必然不能匹配到。
四、排查结果
再看一下,我们的系统卡住不同步的event:
#171214 6:31:30 server id ** end_log_pos ** group_id ** Table_map: `**`.`heartbeat` mapped to number 6865731036
#171214 6:31:30 server id ** end_log_pos ** group_id ** Update_rows: table id 6865731036 flags: STMT_END_F exec_time=0
可以看出,6865731036已远远超过uint的最大值4294967295。对,我们这次的问题就是因为table_id溢出导致的。
table_id变这么大的原因:
1、表数量多(近6万张表),而table_open_cache参数设置较小(1000),导致表不断从内存中换入换出,而每换入换出一次table_id都会递增
2、运行时间长(500多天),导致table_id一直往上增长
五、处理方法
减小或者控制table_id增长速度:
1、增大table_open_cache大小,使表从内存中交换次数降低,从而使table_id计数不是那么快速上涨
2、定期重启MySQL实例,让table_id重新开始计数
3、binlog_format在允许的条件下,可以改为statement格式(没有table_map_event和row_log_event问题)
4、升级数据库到 5.6(5.6.11已解决该bug)
六、预案
站在当时的角度,该问题确实难以想到更好的办法去解决,当时处理过程相当坎坷,最后单点的主库因为内存炸掉导致重启,整个服务挂掉近1个小时。后来又经过通过dts同步数据+人肉补数据等不堪回首的处理过程,说多了都是泪。
但是目前来看,我们是可以提前或者快速解决该问题的:
如果遇到table_id溢出导致从库无法同步的问题时,可以选择用dts(通过解析出binlog中的SQL来进行回放)绕过直接通过原生的relation复制来同步数据,当有从库跟主库同步完成后,快速做次主从切换将无问题从库提为主库,其他从库同步该新主即可。
七、参考文章
- 《FAQ系列 | table id问题导致主从复制失败》 http://imysql.com/2016/07/08/mysql-faq-tableid-cause-replication-failed.shtml
- 《【MySQL】再说MySQL中的 table_id》 http://m.blog.itpub.net/22664653/viewspace-1158547/
- 《overflow caused replication sql thread failed to execute events》 https://bugs.launchpad.net/percona-server/+bug/1070255