ITPub博客
首页 博客 专栏 学院 社区 IT新媒体评选
发博

首页 > > > mysqlbinlog工具使用的几个疑惑点和解释

mysqlbinlog工具使用的几个疑惑点和解释

作者：u_ea6ef15d346a 时间：2017-01-03 13:58:33 0 删除 编辑
1、Format_description_event问题：
BINLOG '
kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW
kTXkUyAKAAAALQAAAOgEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
'/*!*/;
假设以上是使用 ../mysql/bin/mysqlbinlog -v --start-position=1094 mysql-bin.000036生成的一个BINLOG，类型为 DELETE_ROW_LOG_EVENT。内容如下：
### DELETE FROM `test`.`t3`
### WHERE
###   @1=1
### DELETE FROM `test`.`t3`
### WHERE
###   @1=2
mysql客户端，单独执行这个binlog无法达到删除t3中 (1), (2)这两行的目的。报错如下：
mysql> BINLOG '
kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW
kTXkUyAKAAAALQAAAOgEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
'/*!*/;
ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.
mysql>
DBA刚开始误以为是个mysql bug。其实不然。
错误提示需要先执行format description BINLOG，即需要先执行Format_description_event，该binlog用于描述接下来要执行的BINLOG的版本等信息，如下：
# at 4
#140808 10:26:53 server id 10  end_log_pos 121 CRC32 0x5731b21e Start: binlog v 4, server v 5.6.19-log created 140808 10:26:53
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
bTXkUw8KAAAAdQAAAHkAAAABAAQANS42LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXQAEGggAAAAICAgCAAAACgoKGRkADQEe
sjFX
'/*!*/;
该BINLOG位于每个binlog文件偏移位置4开始。
似乎是合理的，在mysql-5.5.30版本中，DBA第二次执行原来的DELETE_ROW_LOG_EVENT时，却能够执行成功。这似乎不合理。其实第二次执行也不应该成功，这是mysql-5.5.30的一个bug
链接为：Bugs : Percona Server
在mysql 5.6.19验证了下，该bug已经修复：
mysql> BINLOG 'kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW 
kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
'/*!*/;
ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.
mysql> BINLOG 'kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW 
kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
'/*!*/;
ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.
mysql> 
mysql> BINLOG 'kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW 
kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
'/*!*/;
ERROR 1609 (HY000): The BINLOG statement of type `Table_map` was not preceded by a format description BINLOG statement.
mysql>
即不管执行多少次同一个BINLOG，都无法成功。除非先执行了Format_description_event：
mysql> BINLOG '                                                                                                                                       
    '> bTXkUw8KAAAAdQAAAHkAAAABAAQANS42LjE5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
    '> AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXQAEGggAAAAICAgCAAAACgoKGRkADQEe
    '> sjFX
    '> '/*!*/;  //这是一个Format_description_event
Query OK, 0 rows affected (0.00 sec)

mysql> BINLOG '
    '> kTXkUxMKAAAALQAAAPoDAAAAAEgAAAAAAAEABHRlc3QAAnQzAAEDAAFS1mTW
    '> kTXkUx4KAAAALQAAACcEAAAAAEgAAAAAAAEAAgAB//4BAAAA/gIAAAC52uck
    '> '/*!*/;
Query OK, 0 rows affected (0.00 sec)
2、执行binlog时“0 rows affected”问题
这样就成功得将对应的t3中对应的(1),(2)删掉。但问题也来了，为什么执行完显示 “Query OK, 0 rows affected (0.00 sec)”。这个让人很费解。
“0 rows affected” 这个问题，也是有DBA提出来了，他们在使用mysqlbinlog -B 进行flashback操作时，执行过程一直是“Query OK, 0 rows affected (0.00 sec)”，怀疑
flashback功能出了问题。其实是因为执行BINLOG直接调用存储引擎的相关接口，跟常规的sql语句执行走的代码路径不完全相同，所以rows affected没有得到正确统计。
继续回到Format_description_event问题上，需要注意的是，在一次客户端连接期间，只需执行一次Format_description_event即可。这个也是好理解的。
3、flashback功能需要与-v配合使用问题
不过mysql的flashback工具确实存在一个问题，就是在flashback update 操作时，需要-v和-B一起作用才能够成功。这是因为：
Rows_log_event::exchange_update_rows在进行set和where内容调换时，需要计算这两段内容的长度，该功能由Rows_log_event::print_verbose_one_row完成，
该函数会根据表定义table_def (td)来获取表中每个field的length，并通过binlog中的记录获取set和where中那几个field是NULL的。
而td是从Table_map_log_event中获取的，且只有在-v时才会生成td：
if (print_event_info->verbose)
  {

    Rows_log_event *ev= NULL;
    Log_event_type et= (Log_event_type) ptr[EVENT_TYPE_OFFSET];

    if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF &&
        checksum_alg != BINLOG_CHECKSUM_ALG_OFF)
      size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header
    
    switch(et)
    {
    case TABLE_MAP_EVENT:
    {
      Table_map_log_event *map; 
      map= new Table_map_log_event((const char*) ptr, size, 
                                   glob_description_event);
      print_event_info->m_table_map.set_table(map->get_table_id(), map);
break;
    }
通过set_table(map->get_table_id(), map)来将对应的map（ td从这里来map->create_table_def() ）放入table的哈希表中；
所以，不加-v进行update操作的flashback解析时，由于无法通过map= print_event_info->m_table_map.get_table(m_table_id)来获取map进而获取td。
导致无法知道表定义，从而无法进行set和where长度的计算并进行内容调换。
为了修复这个bug，修改如下：
if (is_flashback) //Flashback
  {
    uint32 fb_size = size;
if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF &&
 checksum_alg != BINLOG_CHECKSUM_ALG_OFF)
fb_size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header
    switch (ptr[EVENT_TYPE_OFFSET]) {
 //add TABLE_MAP_EVENT, as UPDATE_ROWS_EVENT need to get_table from map
 case TABLE_MAP_EVENT:
 {
Table_map_log_event *map; 
map= new Table_map_log_event((const char*) ptr, fb_size, 
glob_description_event);
print_event_info->m_table_map.set_table(map->get_table_id(), map);
break;
 }
      case WRITE_ROWS_EVENT:
        ptr[EVENT_TYPE_OFFSET]= DELETE_ROWS_EVENT;
        break;
....
  if (print_event_info->verbose)
  {
    Rows_log_event *ev= NULL;
    Log_event_type et= (Log_event_type) ptr[EVENT_TYPE_OFFSET];

    if (checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF &&
        checksum_alg != BINLOG_CHECKSUM_ALG_OFF)
      size-= BINLOG_CHECKSUM_LEN; // checksum is displayed through the header
    
    switch(et)
    {
    case TABLE_MAP_EVENT:
    {
 //if flashback, map has already set into hash above
 if (!is_flashback) 
 {
      Table_map_log_event *map; 
      map= new Table_map_log_event((const char*) ptr, size, 
                                   glob_description_event);
      print_event_info->m_table_map.set_table(map->get_table_id(), map);
 }
 break;
    }
4、mysqlbinlog解析relay log报“unknown table”问题
组内的小伙伴在做基于relay-log进行的数据库实例故障恢复时，发现mysqlbinlog的又一个bug，社区之前也已提及，如下：row based relay log events are lost from mysqlbinlog output。大意是在使用mysqlbinlog解析高可用数据库实例从库的relay log时，提示“### Row event for unknown table #16#”，简单分析可知该提示是说DML操作（UPDATE/INSERT/DELETE）所需的table map找不到了，而table map可以将table id（上述的16）跟表定义建立关联。没有table map当然就无法解析DML操作。
那么table map真的不见了吗？其实不然，只是table map位于上一个relay log文件而已。那么，既然mysqlbinlog能够同时解析多个文件，能不能将上一个文件跟当前文件一起解析，这样应该就不会报这个错误了吧。我刚开始也是这么认为的，还跟小伙伴争了，结果应了那句：“没有调查就没有发言权”。小伙伴可是试验过了，结果还是无法解析。个人觉得这不合理啊。
为此，看了mysqlbinlog的代码，很快就找到了问题所在，下面进行简单分析
1、mysqlbinlog用一个for循环来处理一个或多个binlog文件，如下：

// main loop:
 for (save_stop_position= stop_position, stop_position= ~(my_off_t)0 ; (--argc >= 0) ; ) 
{ 
if (argc == 0) // last log, --stop-position applies stop_position= save_stop_position; 
if ((retval= dump_log_entries(*argv++)) != OK_CONTINUE) 
    break; 
// For next log, --start-position does not apply 
start_position= BIN_LOG_HEADER_SIZE; 
}
这个循环代码很是简练，以至于刚开始看代码的还是，根本不知道是什么意思。其实，循环中argc表示有几个binlog文件需要解析，*argv表示具体的文件名称。start-position和stop_position处理得也很奇妙，在此不细说。

2、有以上的铺垫可以知道，dump_log_entries函数是用来处理每个binlog文件的。
/**
  High-level function for dumping a named binlog.
  This function calls dump_remote_log_entries() or
  dump_local_log_entries() to do the job.
  @param[in] logname Name of input binlog.
  @retval ERROR_STOP An error occurred - the program should terminate.
  @retval OK_CONTINUE No error, the program should continue.
  @retval OK_STOP No error, but the end of the specified range of
  events to process has been reached and the program should terminate.
*/
static Exit_status dump_log_entries(const char* logname)
{
  Exit_status rc;
  PRINT_EVENT_INFO print_event_info;
  if (!print_event_info.init_ok())
    return ERROR_STOP;
  if (!only_event_info)
  {
  /*
     Set safe delimiter, to dump things
     like CREATE PROCEDURE safely
  */
  fprintf(result_file, "DELIMITER /*!*/;\n");
  strmov(print_event_info.delimiter, "/*!*/;");
  }
  
  print_event_info.verbose= short_form ? 0 : verbose;
  rc= (remote_opt ? dump_remote_log_entries(&print_event_info, logname) :
       dump_local_log_entries(&print_event_info, logname));

  if (!only_event_info)
  {
  if (!flashback_opt)
  {
  /* Set delimiter back to semicolon */
    fprintf(result_file, "DELIMITER ;\n");
    strmov(print_event_info.delimiter, ";");
  }
  }

  return rc;
}
根据解析的binlog是否为远程的，又分为dump_remote_log_entries和dump_local_log_entries，我们主要用了dump_local_log_entries，进入函数后我们会发现，mysqlbinlog使用Log_event::read_log_event(file, glob_description_event)和process_event(print_event_info, ev, old_off, logname)两个函数来读取、构建和解析每个binlog。我们应该关注的是print_event_info，这个是控制整个解析过程的关键对象。比如说，如果binlog的类型是TABLE_MAP_EVENT （这个就是问题所在，保存table map的地方），那么在解析时，会将table id和具体的表定义联系起来。并记录到print_event_info中。process_event在处理WRITE_ROWS_EVENT/UPDATE_ROWS_EVENT/DELETE_ROWS_EVENT(对应前述的DML操作)时，由于event中仅记录所操作的表的table id，所以就需要借助print_event_info来获取对应的映射关系。跨relay log的事务在使用mysqlbinlog进行解析时出错的原因就在于，print_event_info是在dump_log_entries中定义的。在完成一个binlog文件的解析后会自动销毁掉，无法继承给下一个待解析的binlog文件。
所以，解决问题的办法很简单，将PRINT_EVENT_INFO print_event_info定义提取出来，设为mysqlbinlog的全局变量即可解决问题。
之前有小伙伴提问，为什么不把表定义直接记录到DML操作中，答案是显而易见的，如果每个DML的binlog都记录表定义，一是没有必要，二是太浪费存储空间了。

原文作者：；如有侵权，请联系管理员删除。

0
0
上一篇： 使用cypher和gremlin进行图随机游走
下一篇： MySQL Group Replication内存使用分析和优化-1
请登录后发表评论 登录
全部评论
u_ea6ef15d346a

注册时间：2019-12-12

  • 博文量
    120
  • 访问量
    483

最新文章

支持我们 作者招募 用户协议 FAQ Contact Us

北京盛拓优讯信息技术有限公司. 版权所有  京ICP备16024965号-8 北京市公安局海淀分局网监中心备案编号：11010802021510 niuxiaotong@pcpop.com 17352615567 未成年人举报专区

广播电视节目制作经营许可证(京) 字第1234号 中国互联网协会会员

违法和不良信息举报电话:18101376593