為什么在MySQL雙主單寫(xiě)的情況下主庫偶爾出現大量

為什么在雙主單寫(xiě)的情況下主庫偶爾出現大量延遲，相信很多沒(méi)有經(jīng)驗的人對此束手無(wú)策，為此本文總結了問(wèn)題出現的原因和解決方法，通過(guò)這篇文章希望你能解決這個(gè)問(wèn)題。

我們是雙主單寫(xiě)，這里約定寫(xiě)入的庫為主庫，沒(méi)有寫(xiě)入的庫為從庫。我們的falcon偶爾會(huì )進(jìn)行報警如下（頻率很低）：

這是非常奇怪的，按理說(shuō)我是單寫(xiě)的從庫沒(méi)有做任何操作（除了應用Event以外），主庫哪來(lái)的延遲，并且延遲這么大。在我映像中有朋友問(wèn)過(guò)這個(gè)問(wèn)題，當時(shí)沒(méi)有細細研究。

二、延遲計算的規則

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

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

計算延遲的公式為：

long time_diff= ((long)(time(0)
                          - mi->rli->last_master_timestamp)
                          - mi->clock_diff_with_master);
也就是：
當前時(shí)間-Event header中的timestamp - 主從服務(wù)器時(shí)間差

出現延遲的必要條件：

• 如果SQL線(xiàn)程沒(méi)有應用完了所有的IO線(xiàn)程寫(xiě)入的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()))

  拋開(kāi)文件名，也就是通過(guò) IO線(xiàn)程讀取到主庫binary log的位置 和 SQL線(xiàn)程應用到的主庫binary log位置進(jìn)行比較來(lái)進(jìn)行 判斷，只要他們出現差值就會(huì )進(jìn)入延遲計算環(huán)節。

• 服務(wù)器當前時(shí)間-Event header中的timestamp - 主從服務(wù)器時(shí)間差 這個(gè)公式必須出現差值。

好了接下來(lái)帶著(zhù)這兩個(gè)產(chǎn)生延遲的必要條件來(lái)尋求原因。

三、產(chǎn)生延遲的原因

1.主庫：首先主庫寫(xiě)到從庫的Event，從庫會(huì )寫(xiě)入到binlog（log_slave_updates 開(kāi)啟），并且從庫的DUMP線(xiàn)程會(huì )發(fā)送給主庫，但是主庫的IO線(xiàn)程通過(guò)SERVER_ID進(jìn)程判定，將Event進(jìn)行過(guò)濾，不寫(xiě)入主庫的relay log，同時(shí)會(huì )更新主庫IO線(xiàn)程讀取的位置（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位點(diǎn)，為當前位置 
      memcpy(rli->ign_master_log_name_end, mi->get_master_log_name(), FN_REFLEN); //進(jìn)行拷貝
      DBUG_ASSERT(rli->ign_master_log_name_end[0]); //斷言存在
      rli->ign_master_log_pos_end= mi->get_master_log_pos(); //忽略到位點(diǎn)
    }

1. 主庫：SQL線(xiàn)程會(huì )通過(guò)rli->ign_master_log_name_end[0]判定是否有需要跳過(guò)的Event，如果有則構建一個(gè)Rotate_log_event來(lái)跳過(guò)這個(gè)Event，代碼如下：

if (rli->ign_master_log_name_end[0]) //如果跳過(guò)的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); //構建一個(gè)Rotate Event，位置為
          rli->ign_master_log_name_end[0]= 0;                   //rli->ign_master_log_pos_end，執行這個(gè)Event就可以
          mysql_mutex_unlock(log_lock);exec_relay_log_event     //來(lái)更新Exec_Master_Log_Pos位點(diǎn)
          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在主庫是如何跳過(guò)的，但是注意IO線(xiàn)程和SQL線(xiàn)程在處理Read_Master_Log_Pos和Exec_Master_Log_Pos的時(shí)候可能有一定的時(shí)間差，那么Read_Master_Log_Pos和Exec_Master_Log_Pos存在一定的差值 的條件就可能會(huì )滿(mǎn)足，則進(jìn)入延遲計算環(huán)節。

1. 主庫的SQL線(xiàn)程平時(shí)并沒(méi)有讀取到Event，因為所有的Event都被IO線(xiàn)程過(guò)濾掉了。因此
   Event的 header中的timestamp 不會(huì )更新（MTS）。但是如果從庫binlog切換的時(shí)候，從庫至少會(huì )傳送ROTATE_EVENT給主庫，這個(gè)時(shí)候主庫會(huì )拿到這個(gè)實(shí)際的Event，因此Event的 header中的timestamp 更新了。 如果剛好遇到主庫的IO線(xiàn)程的Read_Master_Log_Pos和Exec_Master_Log_Pos有差值，
   那么falcon去查看延遲就會(huì )得到一個(gè)延遲很大的假象，延遲的計算公式就會(huì )變?yōu)槿缦拢?/p>

• 主庫當前的時(shí)候 - 從庫上次binlog切換的時(shí)間 - 主從時(shí)間的差值

1. MTS和單線(xiàn)程的不同

上面的第3點(diǎn)只適用于MTS，單SQL線(xiàn)程不同，會(huì )去將last_master_timestamp設置為0，代碼如下：

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

言外之意單SQL線(xiàn)程計算延遲的公式為：

• 主庫當前的時(shí)間 - 1970年1月1日0點(diǎn) - 主從時(shí)間的差值

因此看起來(lái)計算出來(lái)的延遲會(huì )更大。

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

四、MTS下的延遲debug

其實(shí)知道了原理就很容易debug了，因為我們可以將斷點(diǎn)放到主庫的show_slave_status_send_data函數上，那么就能看出來(lái)了，做的操作如下：

• 從庫flush binary logs

• 主庫執行一些insert操作

• 主庫show slave status

這個(gè)時(shí)候我們可以跳過(guò)（Read_Master_Log_Pos和Exec_Master_Log_Pos存在一定的差值）這個(gè)條件，直接通過(guò)公式去計算，得到如下結果：

(gdb) p (long)(time(0)- mi->rli->last_master_timestamp)- mi->clock_diff_with_master
$6 = 37

延遲就是37秒，因此我們的理論得到了驗證。

下面一個(gè)debug結果是單SQL線(xiàn)程的，可以看到延遲更是大得離譜。

(gdb) p (long)(time(0)- mi->rli->last_master_timestamp)- mi->clock_diff_with_master
$7 = 1592672402

五、其他問(wèn)題

額外的問(wèn)題：

• 如果雙主雙寫(xiě)

如果按照上面的理論那么T3的更新的位置可能會(huì )被，T2事務(wù)的位點(diǎn)重置。因為主庫的SQL線(xiàn)程通過(guò)構建的Rotate_log_event可能會(huì )出現Exec_Master_Log_Pos倒退的可能性，這顯然是不行的。但是代碼中構建Rotate_log_event的邏輯包裹在如下邏輯下面。

if (!cur_log->error) /* EOF */ //當前relay log 已經(jīng)讀取完了
    {
      /*
        On a hot log, EOF means that there are no more updates to
        process and we must block until I/O thread adds some and
        signals us to continue
      */
      if (hot_log) //如果是 當前relay log

我們可以看到只有在當前 relay log讀取完成后才會(huì )進(jìn)行Rotate_log_event的構建。因此不存在此問(wèn)題。

• 問(wèn)題如上雖然不構建Rotate_log_event，但是如果rli->ign_master_log_name_end[0]如果一直保留那么當relay log應用完成后，依舊會(huì )去構建Rotate_log_event導致Exec_Master_Log_Pos倒退，實(shí)際上這個(gè)問(wèn)題也不會(huì )出現，因為在每次IO線(xiàn)程Event寫(xiě)入到relay log后會(huì )重置，如下：

    rli->ign_master_log_name_end[0]= 0; // last event is not ignored