MySQL 雙主單寫，主庫偶爾出現大量延遲的原因(1)

水準有限有誤請諒解

一、問題來源

這是來自我們線上資料庫的一個問題。我們是雙主單寫，這裡約定寫入的庫為主庫，沒有寫入的庫為從庫。我們的falcon偶爾會進行報警如下（頻率很低）：

這是非常奇怪的，按理說我是單寫的從庫沒有做任何操作（除了應用Event以外），主庫哪來的延遲，并且延遲這麼大。在我映像中有朋友問過這個問題，當時沒有細細研究。

二、延遲計算的規則

我們還是要看看主從計算延遲的僞代碼：

/*
     The pseudo code to compute Seconds_Behind_Master:
     if (SQL thread is running)
//如果SQL線程啟動了
     {
       if (SQL thread processed all the available relay log)
//如果SQL線程已經應用完了所有的IO線程寫入的Event
       {
         if (IO thread is running)
//如果IO線程啟動了
            print 0;
//設定延遲為0
         else
            print NULL;
//否則為空值
       }
        else
          compute Seconds_Behind_Master;
//如果SQL線程沒有應用完所有的IO線程寫入的Event，那麼需要計算延遲。
      }
      else
       print NULL;
//如果連SQL線程也沒有啟動則設定為空值
  */      

計算延遲的公式為：

long time_diff= ((long)(time(0)
                          - mi->rli->last_master_timestamp)
                          - mi->clock_diff_with_master);
也就是：
伺服器目前時間-Event header中的timestamp - 主從伺服器時間差      

出現延遲的必要條件：

• 如果SQL線程沒有應用完了所有的IO線程寫入的Event，也就是Read_Master_Log_Pos和Exec_Master_Log_Pos存在一定的內插補點。判定标準為

(mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
        (!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name()))      

抛開檔案名，也就是通過 IO線程讀取到主庫binary log的位置 和 SQL線程應用到的主庫binary log位置進行比較來進行 判斷，隻要他們出現內插補點就會進入延遲計算環節。

• 伺服器目前時間-Event header中的timestamp - 主從伺服器時間差 這個公式必須出現內插補點。

好了接下來帶着這兩個産生延遲的必要條件來尋求原因。

關于更多延遲計算的細節參考：

https://www.jianshu.com/p/033f83314619

三、産生延遲的原因

1.主庫：首先主庫寫到從庫的Event，從庫會寫入到binlog（log_slave_updates 開啟），并且從庫的DUMP線程會發送給主庫，但是主庫的IO線程通過SERVER_ID程序判定，将Event進行過濾，不寫入主庫的relay log，同時會更新主庫IO線程讀取的位置（Read_Master_Log_Pos），并且更新忽略到的位置（rli->ign_master_log_name_end[0]）。代碼如下：

if (!(s_id == ::server_id && !mi->rli->replicate_same_server_id) ||
        (event_type != binary_log::FORMAT_DESCRIPTION_EVENT &&
         event_type != binary_log::ROTATE_EVENT &&
         event_type != binary_log::STOP_EVENT))
    {
      mi->set_master_log_pos(mi->get_master_log_pos() + inc_pos);//增加Read_Master_Log_Pos位點，為目前位置
      memcpy(rli->ign_master_log_name_end, mi->get_master_log_name(), FN_REFLEN); //進行拷貝
      DBUG_ASSERT(rli->ign_master_log_name_end[0]); //斷言存在
      rli->ign_master_log_pos_end= mi->get_master_log_pos(); //忽略到位點
    }      

1. 主庫：SQL線程會通過rli->ign_master_log_name_end[0]判定是否有需要跳過的Event，如果有則建構一個Rotate_log_event來跳過這個Event，代碼如下：

if (rli->ign_master_log_name_end[0]) //如果跳過的Event存在
        {
          /* We generate and return a Rotate, to make our positions advance */
          DBUG_PRINT("info",("seeing an ignored end segment"));
          ev= new Rotate_log_event(rli->ign_master_log_name_end,
                                   0, rli->ign_master_log_pos_end, exec_relay_log_event
                                   Rotate_log_event::DUP_NAME); //建構一個Rotate Event，位置為
          rli->ign_master_log_name_end[0]= 0;                   //rli->ign_master_log_pos_end，執行這個Event就可以
          mysql_mutex_unlock(log_lock);exec_relay_log_event     //來更新Exec_Master_Log_Pos位點
          if (unlikely(!ev))
          {
            errmsg= "Slave SQL thread failed to create a Rotate event "
              "(out of memory?), SHOW SLAVE STATUS may be inaccurate";
            goto err;
          }
          ev->server_id= 0; // don't be ignored by slave SQL thread
          DBUG_RETURN(ev);
        }      

好了到這裡我們知道了Event在主庫是如何跳過的，但是注意IO線程和SQL線程在處理Read_Master_Log_Pos和Exec_Master_Log_Pos的時候可能有一定的時間差，那麼Read_Master_Log_Pos和Exec_Master_Log_Pos存在一定的內插補點 的條件就可能會滿足，則進入延遲計算環節。

1. 主庫的SQL線程平時并沒有讀取到Event，因為所有的Event都被IO線程過濾掉了。是以

   Event的 header中的timestamp 不會更新（MTS）。但是如果從庫binlog切換的時候，從庫至少會傳送ROTATE_EVENT給主庫，這個時候主庫會拿到這個實際的Event，是以Event的 header中的timestamp 更新了。如果剛好遇到主庫的IO線程的Read_Master_Log_Pos和Exec_Master_Log_Pos有內插補點，

   那麼falcon去檢視延遲就會得到一個延遲很大的假象，延遲的計算公式就會變為如下：

• 主庫目前的時候 - 從庫上次binlog切換的時間 - 主從時間的內插補點

1. MTS和單線程的不同

上面的第3點隻适用于MTS，單SQL線程不同，會去将last_master_timestamp設定為0，代碼如下：

if (!rli->is_parallel_exec())
          rli->last_master_timestamp= 0;      

言外之意單SQL線程計算延遲的公式為：

• 主庫目前的時間 - 1970年1月1日0點 - 主從時間的內插補點

是以看起來計算出來的延遲會更大。

1. 最後需要注意的是實際上這種情況的延遲并沒有問題，完全是一種偶爾出現的計算上的問題，是一種假象，如果主庫的壓力越大出現這種情況的可能性就會越大，因為IO線程和SQL線程在處理Read_Master_Log_Pos和Exec_Master_Log_Pos的出現時間差的可能性就會越大。