前言

日常Bug排查系列都是一些簡單Bug的排查。筆者將在這里介紹一些排查Bug的簡單技巧，同時順便積累素材。

Bug現場

線上連續兩天出現NP異常，而且都是凌晨低峰期才出現，在凌晨的流量遠沒有白天高峰期大。而出問題的接口又是通常的業務請求。于是，很自然的，我們就想凌晨有什么特殊的運維動作，翻了下時間線。發現，每天凌晨都會進行改表，而修改的這張表恰好就是出現NP異常的表。如下圖所示：

在此解釋下業務的相關場景。A表是主表，B表是子表，兩者都是嚴格保證在一個事務內一塊插入和更新的，在該表時刻確出現了在一個事務內查詢，能查到A確查不到B的現象。

思路

數據庫的一個核心特性就是原子性，看上去這個場景破壞了原子性。但是由于是和改表強相關，其它時間沒有類似錯誤。那么很明顯的，思路就會指向該表這個動作會短暫的破壞原子性。由于線上使用的ghost進行改表，于是筆者就看了下ghost改表的原理：

ghost會創建一個影子表，在影子表上完成alter改表，然后分批將全量數據應用到新表。
同時在處理增量數據的時候，通過解析binLog事件，將任務期間的新增數據應用到新表。
最后一步，通過Rename語句使新表替換老表

從這個原理中可以推斷，最后一步Rename的時候才會對當前的SQL產生影響，是不是剛好這個這個Rename操作短暫的使讀數據不一致了呢？看了下DBA那邊的改表日志，發現Rename那個時刻和NP異常出現時刻完全吻合?？磥硭褪亲锟準琢恕?/p>

為什么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);
  }
    ......
}

總結

線上環境是錯綜復雜的，改表等運維操作也會導致出現意料之外的結果，很多組件的特性在一些特殊的情況下會被打破，所以防御式編程就顯得尤其重要了。