【MySQL BUG】线上系统因table_id溢出导致主从复制无法进行总结

  1. 云栖社区>
  2. 博客>
  3. 正文

【MySQL BUG】线上系统因table_id溢出导致主从复制无法进行总结

shuangbest 2017-12-18 00:51:35 浏览2136
展开阅读全文
一、背景
    上周,所负责一个系统遇到MySQL的bugBug #67352,导致所有从库卡在某一个点无法继续同步主库的更新。具体表现:主库后面挂载的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重新开始计数
    3binlog_format在允许的条件下,可以改为statement格式(没有table_map_event和row_log_event问题)
    4、升级数据库到 5.6(5.6.11已解决该bug)

六、预案
    站在当时的角度,该问题确实难以想到更好的办法去解决,当时处理过程相当坎坷,最后单点的主库因为内存炸掉导致重启,整个服务挂掉近1个小时。后来又经过通过dts同步数据+人肉补数据等不堪回首的处理过程,说多了都是泪。
    但是目前来看,我们是可以提前或者快速解决该问题的:
    如果遇到table_id溢出导致从库无法同步的问题时,可以选择用dts(通过解析出binlog中的SQL来进行回放)绕过直接通过原生的relation复制来同步数据,当有从库跟主库同步完成后,快速做次主从切换将无问题从库提为主库,其他从库同步该新主即可。

七、参考文章

网友评论

登录后评论
0/500
评论