semi-sync插件崩溃导致MySQL重启的故障分析全过程~

作者：刘安

现为爱可生高级测试工程师，拥有丰富的自动测试开发经验；曾先后在文思海辉、Splunk担任测试工程师。

在公司测试MySQL高可用组件时发现一个异常。如下：

二、环境：

三、分析：

(一）首先，分析log文件：

（二）其次，进一步验证：

1. 启停semi-sync master；
2. 数据库当时有事务提交。

（三）最后分析MySQL源码：

这正是我想要的修复和提交，打开看看有没有对产生故障原因的分析，Bug#22202516: ENABLING SEMI-SYNC DURING COMMIT CAN CAUSE MASTER TO ASSERT。

为了方便解释这个BUG, 这里先简单的介绍一下MySQL binlog提交过程：MySQL 在5.6版本引入了Binary Log Group Commit，二进制日志的提交由此可以简化为三个阶段： 

• Flush stage：将事务的日志写入binlog文件的缓存中
• Sync stage: 将binlog文件中的缓存数据写入磁盘
• Commit stage：根据顺序调用存储引擎提交事务

在BUG分析中提到：

• 首先在flush stage，由semi-sync创建一个‘entry’，并关联一个或一组处于flush stage的事务。这个‘entry’被插入一个active transaction链表。 参考: create entry。
  int ReplSemiSyncMaster::writeTranxInBinlog(const char* log_file_name, my_off_t log_file_pos)
  {
  ...
  if (is_on())
  {
  assert(active_tranxs_ != NULL);
  if(active_tranxs_->insert_tranx_node(log_file_name, log_file_pos))
  {
  /*
  if insert tranx_node failed, print a warning message
  and turn off semi-sync
  */
  sql_print_warning("Semi-sync failed to insert tranx_node for binlog file: %s, position: %lu",
  log_file_name, (ulong)log_file_pos);
  switch_off();
  }
  }
  ...
  }
• 接下来是sync stage，在sync stage每个处于这个阶段的线程将会设置trx_wait_binlog_name和trx_wait_binlog_pos为事务对应binlog的相对位置；
• 最后再commit stage，semi-sync为了等从库的确认，会用trx_wait_binlog_name和trx_wait_binlog_pos获取这个位置关联的'entry', 参考: find entry；
  int ReplSemiSyncMaster::commitTrx(const char* trx_wait_binlog_name, my_off_t trx_wait_binlog_pos)
  {
  ...
  TranxNode* entry= NULL;
  mysql_cond_t* thd_cond= NULL;
  if (active_tranxs_ != NULL && trx_wait_binlog_name)
  {
  entry=
  active_tranxs_->find_active_tranx_node(trx_wait_binlog_name,
  trx_wait_binlog_pos);
  if (entry)
  thd_cond= &entry->cond;
  }
  ...
  }

四、结论：

最终修复的结果也很明显，就是遇到找不到‘entry’并且从库也没有确认的情况，这个事务提交就被认为是一次异步提交。

五、复盘：

1. 观察故障出现的现象，分析MySQL的error log；
2. 通过猜想和实验，构成简单的复现场景；
3. 通过日志和MySQL源码的对应关系, 搜索代码历史, 定位BUG号；
4. 通过阅读BUG的分析，了解异常发生的原理并知道了详细的复现条件。