小编点评

# 前言 日常Bug排查系列文章将介绍一些简单Bug的排查技巧，并积累素材。本文将介绍一个实际案例中的Bug排查过程。 # 现场问题 某天，线上服务出现了一个NP异常，问题出现在凌晨低峰期。经过分析，发现问题出现在一个业务请求上，而且这个问题在每天的凌晨都会出现。通过查看时间线，发现每天凌晨都会进行改表操作，而这个表正是出现NP异常的表。 ## 业务场景 A表是主表，B表是子表，两者都需要在一个事务内一块插入和更新。在这个表上，我们发现在一个事务内查询时，能查到A表的数据，但是查不到B表的数据。 ## 数据库特性 数据库的一个核心特性是原子性。在这个场景中，这个特性被破坏了。但是其他时间没有出现类似的错误。因此，我们可以推测这个表的操作会短暂地破坏原子性。 ## 问题定位 通过研究Ghost改表的原理，我们发现最后一步Rename操作才会对当前的SQL产生影响。我们可以推断，最后一步Rename操作可能会导致读数据不一致。 查看DBA的改表日志，我们发现Rename操作的时刻与NP异常出现的时刻完全吻合。这证实了我们的推测。 ## 原因分析 最终导致问题的原因是：BNew新表通过Ghost的binlog重放将原B表中相关的binLog重放到BNew表中。但是在事务T2开始的时候，BNew这张表中新纪录B还没有被重放。在事务T2开始的时候首先查询了A表建立了MVCC视图，这时候的数据库实际快照就是A表有A，BNew表没有B。尽管在Rename表的时候MySQL会对B和BNew都进行锁表，这时候所有对于这两张表的访问都会等锁表的结束。但是由于RR的原因，这个事务内后续读BNew表的时候始终就是A表有A，BNew表没有B这样的现象。在后续的查询中select B查询的实际上是BNew表，进而产生了数据不一致，进而导致了NullPointerException。 ## 测试验证 为了验证我们的推理，我们在线下设计相关实验复现问题。我们模拟了事务顺序，新建一张BNew表然后Rename下，发现现象并不一致。在Rename的时候，模拟的请求2在做select新B表的时候始终会出现Table definition has changed,please retry transaction这个报错。 查阅MySQL源代码，我们发现要让Rename不报错，必须在模拟的请求2事务开始之前就创建这个BNew表。否则请求2在查询BNew表的时候就会由于找不到UndoHistory导致报错。 # 总结 线上环境是错综复杂的，改表等运维操作也会导致出现意料之外的结果。很多组件的特性在一些特殊的情况下会被打破，所以防御式编程就显得尤其重要。在实际工作中，我们需要积累经验，提高自己的技术能力，以便更好地应对这类问题。

正文

前言

日常Bug排查系列都是一些简单Bug的排查。笔者将在这里介绍一些排查Bug的简单技巧，同时顺便积累素材。

Bug现场

线上连续两天出现NP异常，而且都是凌晨低峰期才出现，在凌晨的流量远没有白天高峰期大。而出问题的接口又是通常的业务请求。于是，很自然的，我们就想凌晨有什么特殊的运维动作，翻了下时间线。发现，每天凌晨都会进行改表，而修改的这张表恰好就是出现NP异常的表。如下图所示：

在此解释下业务的相关场景。A表是主表，B表是子表，两者都是严格保证在一个事务内一块插入和更新的，在该表时刻确出现了在一个事务内查询，能查到A确查不到B的现象。

思路

数据库的一个核心特性就是原子性，看上去这个场景破坏了原子性。但是由于是和改表强相关，其它时间没有类似错误。那么很明显的，思路就会指向该表这个动作会短暂的破坏原子性。由于线上使用的ghost进行改表，于是笔者就看了下ghost改表的原理：

ghost会创建一个影子表，在影子表上完成alter改表，然后分批将全量数据应用到新表。
同时在处理增量数据的时候，通过解析binLog事件，将任务期间的新增数据应用到新表。
最后一步，通过Rename语句使新表替换老表

从这个原理中可以推断，最后一步Rename的时候才会对当前的SQL产生影响，是不是刚好这个这个Rename操作短暂的使读数据不一致了呢？看了下DBA那边的改表日志，发现Rename那个时刻和NP异常出现时刻完全吻合。看来它就是罪魁祸首了。

为什么Rename会导致读数据不一致？

笔者稍加思索就明白了原因。首先，线上库的隔离级别是RR的，也就是可重复读。而Alter表的时候势必会有一张旧表B和新表BNew。业务的事务保证是操作在A和B上的，而读数据不一致应该是A和BNew上，所以无法保证A和BNew的一致。只能通过binLog的重放保证最终一致。 那么最终导致问题的原因就很明显了，如下所示：

BNew新表通过ghost的binlog重放将原B表中相关的binLog重放到BNew表中。但是在事务T2开始的时候BNew这张表中新纪录B还没有被重放。在事务T2开始的时候首先查询了A表建立了MVCC视图，这时候的数据库实际快照就是A表有A，BNew表没有B。尽管在Rename表的时候MySQL会对B和BNew都进行锁表，这时候所有对于这两张表的访问都会等锁表的结束。但是由于RR的原因，这个事务内后续读BNew表的时候始终就是A表有A，BNew表没有B这样的现象。在后续的查询中select B查询的实际上是BNew表，进而产生了数据不一致，进而导致了NullPointerException。

测试复现实验的一个小问题

还有一个小问题，就是笔者在线下设计相关实验复现问题的时候。这个复现的实验看上去是比较容易的，模拟一下事务顺序，新建一张BNew表然后Rename下，看看现象是否一致就可以了，如下图所示:

但笔者发现，在Rename的时候，模拟的请求2在做select 新B表的时候始终会出现

Table definition has changed,please retry transaction

这个报错。于是笔者看了下MySQL的源代码，要想让Rename不报错，必须在模拟的请求2事务开始之前就创建这个BNew表，否则请求2在查询BNew表的时候就会由于找不到UndoHistory导致报错。MySQL源代码如下所示：

row_vers_old_has_index_entry(......){

  ......
  /* If purge can't see the record then we can't rely on
  the UNDO log record. */

  bool purge_sees = trx_undo_prev_version_build(
   rec, mtr, version, index, *offsets, heap,
   &prev_version, NULL, vrow, 0);
  // 在这边，如果找不到这张表在t1前的undo history的话，则会报"Table definition has changed, please retry transaction"
  err  = (purge_sees) ? DB_SUCCESS : DB_MISSING_HISTORY;

  if (prev_heap != NULL) {
   mem_heap_free(prev_heap);
  }
    ......
}

总结

线上环境是错综复杂的，改表等运维操作也会导致出现意料之外的结果，很多组件的特性在一些特殊的情况下会被打破，所以防御式编程就显得尤其重要了。