DM 中 relay log 效能優化實踐丨TiDB 工具分享

語言: CN / TW / HK

前言

Relay log 類似 binary log,是指一組包含資料庫變更事件的檔案,加上相關的 index 和 mata 檔案,具體細節參考 官方文件 。在 DM 中針對某個上游開啟 relay log 後,相比不開啟,有如下優勢:

  • 不開啟 relay log 時,每個 subtask 都會連線上游資料庫拉取 binlog 資料,會對上游資料庫造成較大壓力,而開啟後,只需建立一個連線拉取 binlog 資料到本地,各個 subtask 可讀取本地的 relay log 資料。

  • 上游資料庫對 binlog 一般會有一個失效時間,或者會主動 purge binlog,以清理空間。在不開啟 relay log 時,如果 DM 同步進度較為落後,一旦 binlog 被清理,會導致同步失敗,只能重新進行全量遷移;開啟 relay log 後,binlog 資料會被實時拉取並寫入到本地,與當前同步進度無關,可有效避免前面的問題。

但在 DM 版本 <=  v2.0.7 中,開啟 relay log 後有如下問題:

  • 資料同步延遲相比不開啟 relay log 有明顯上升,下面的表格是一個單 task 的 benchmark 的測試結果,可看出平均 latency 有明顯的增長。下表中以“.”開頭的是延遲的百分位資料。

  • 開啟 relay 後 CPU 消耗增加。(由於 latency 的增長,在一些簡單場景下(比如只有 1 個 task)相比不開啟 relay log,資源使用率反而是下降的。但當 task 增多時,開啟 relay 的 CPU 消耗就增加了)。

由於以上問題,在新的版本中,我們對 DM 的 relay log 做了一些效能優化。

當前 relay 實現

在開始介紹具體的優化之前,首先簡單介紹下當前 DM 中 relay 的實現,詳細實現,詳情可參閱 DM 原始碼閱讀系列文章(六)relay log 的實現 ,本文在此不做過多描述。

當前 relay 模組可以分為兩個部分,relay writer 和 relay reader 部分,其結構如下所示:

Relay writer

relay writer 依次做了下述 3 個事情:

1. 使用 binlog reader 從上游 MySQL/MariaDB 讀取 binlog event;

2. 將讀取到的 binlog event 使用 binlog transformer 進行轉換;

3. 將轉換後的 binlog event 使用 binlog writer 以 relay log file 的形式儲存在本地的 relay directory 中。

Relay reader

開啟 relay 後,Syncer 會通過 relay reader 獲取 binlog event,relay reader 主要是做了如下工作:

  • 讀取 realy directory 中的 binlog 檔案,傳送給 syncer;

  • 當讀取到檔案尾時,定時(目前是每隔 100ms)檢查當前 binlog 檔案大小和 meta 檔案內容是否存在變化,如果改變則繼續讀取(binlog 檔案變化)或者切換到新的檔案(meta 檔案變化)。

從上面的介紹可以看出,relay reader 跟 relay writer 是相互獨立的,彼此通過 relay directory 中的 binlog、meta 和 index 檔案進行互動。

測試環境說明

在開始介紹優化內容前,先介紹下優化時使用的環境情況

  • 上游為 MySQL,版本為   5.7.35-log  ;

  • 下游為單例項的 TiDB,版本為   5.7.25-TiDB-v5.2.1

  • DM 使用了 1 個 master 和 1 個 worker

    • Latency 基準測試版本為 2021-10-14 號的 master 分支(commit hash 為 d2dc22d)

    • CPU 基準測試 版本為 2021-11-01 號的 relay 重構分支(commit hash 為9f7ce1d6)

  • 在小規模測試(<= 4 task)下 MySQL/TiDB/DM 執行在同一主機,方便測試,主機環境為 8 核 16G;

  • 較大規模測試(> 4 task)下 MySQL/TiDB/DM 分別執行在一臺主機上,主機都是 8 核 16G

  • 測量遷移延遲採用下游自更新時間列的方式,詳細參考 多種方式告訴你如何計算 DM 同步資料到 TiDB 的延時時間 中的第三種方式。

Latency 優化

從上面的“ 當前 relay 實現 ”部分可以看出,有兩個可能影響 latency 的點:

  • 當前 relay reader 的定時 check 的實現方式本身就會對 latency 有一定影響,在最壞情況下一個 binlog event 至少要延遲 100ms 才能同步到下游;

  • relay writer 會寫到磁碟,之後 relay reader 從磁碟讀取,這一讀一寫是否會對 latency 有較大影響?

    • 調研發現 linux 系統(Mac OS 系統下也有類似機制)下存在 page cache 的機制,讀取最近寫入的檔案並非通過磁碟,而是讀取 OS 記憶體中的快取,因此理論上影響有限。

經過調研以及對上述問題的測試,我們總結了兩個方案:

  • 在記憶體中快取 relay writer 在最近一段時間內預備寫入的 binlog,如果 relay reader 請求這段 binlog,relay reader 直接從記憶體讀取;

  • relay reader 仍然採用讀取檔案的方式,relay writer 在寫入新的 event 時,通知 relay reader。

方案 1 需要根據下游的寫入速度在讀記憶體和讀檔案之間進行切換,實現起來相對複雜,而且由於 OS 層   page cache 的存在,應用本身再增加一層快取對 latency 的影響有限。

方案 2,我們做了一些初步的測試,在增加 relay reader check 的頻率時,開啟 relay 基本能達到不開啟 relay 時的latency,調研了下 MySQL 的 relay log,發現也是通過讀取檔案的方式,因此我們選擇了方案 2。

實現相對較簡單,在 relay writer 增加了 Listener,在有新 binlog event 時通知該 Listener(往 channel 中傳送一個訊息),然後在 relay reader 中,將 定時 check 改為監聽 channel 中的訊息。

下圖是在 4 table 4 task 測試下的 latency 結果,可以看出開啟 relay 後的 latency 跟不開啟很接近:

CPU 優化

Latency 優化完後,我們也對開啟 relay log 後的 CPU 佔用情況做了測試,發現開啟後 CPU 佔用率也較高,下圖是在 4 table 4 task 下測試結果( 注:後續沒有特殊說明的話,都是在該場景下的測試結果 ),可以看出開啟 relay 後 CPU 消耗有明顯增長,而且尖刺變得更大:

使用 golang 自帶的 pprof 做了一個 CPU profile,從下圖可以看出佔比較大的主要是 syncer/relay reader/relay writer 等部分,對比程式碼邏輯後,發現:

  • Relay reader 使用了 go-mysql 的 ParseFile 介面,該介面每次呼叫都會重新開啟檔案,並讀取第一個 FORMAT_DESCRIPTION 事件,也就是下圖中第一個藍色標註的位置;

  • 在優化 latency 時,由於 relay reader 和 writer 是相互獨立的,為了簡化實現,僅通過 channel 通知是否存在新的 binlog 寫入,而新寫入的 binlog 可能在上次讀取的時候已經讀取過了,這導致了很多無效的 meta、index 檔案的檢查。

針對上面的問題,我們做了如下優化:

  • 使用 go-mysql 的 ParseReader 來消除重複開啟和讀取的消耗;

  • 重構 relay 模組,將 relay writer 和 reader 整合在一起,方便兩者間通訊。relay reader 在通過 channel 收到通知後,檢查當前 relay writer 正在寫入的檔案是否跟正在讀取的檔案相同,即該檔案是否為 active 寫入狀態,並獲取當前檔案寫入的位置,通過這些資訊,可以避免無效的 meta、index 檔案的檢查。

從下圖可以看出優化後 CPU 有較大幅度的降低,但是尖刺仍然較大:

由於我們測試用的 sysbench 產生 write 事件的速率是比較平穩的,DM 中也沒有特別的執行程式碼,而 Golang 是一個編譯型帶 GC 的語言,因此我們猜測尖刺主要來自於 GC,但是這一點從 CPU profile 並不明顯,見下圖:

使用  GODEBUG=gctrace=1  開啟 GC 日誌, 見下圖,可以發現:
  • 開啟 relay 後,駐留記憶體大了接近一倍(239 MB -> 449 MB),Heap 總空間也大了近一倍。

    • 經過調研該問題是由於 DM 內嵌的 tidb 導致的記憶體洩漏,暫時未處理。

  • 開啟 relay 後,GC 佔用的 CPU 大幅增加,特別是 background GC time 和 idle GC time。

下圖是上面優化後做的 heap profile 中 alloc_space 部分的火焰圖:

說明: pprof 的 heap profile 是程式執行至今的一個剖析,並不是某一段時間內,所以從下圖中也可以看到一些駐留記憶體的申請。

通過 heap profile 並對比程式碼,發現了以下可優化的點:

  • Go-mysql 在從檔案解析 binlog event 時,每個 event 都會重新申請一個 bytes.Buffer,並在讀取過程中不斷擴容。優化後改為使用一個 buffer pool,減少不斷擴容帶來的開銷;

  • Local streamer 中 heatbeat event 使用了  time.After ,使用該介面程式碼會更簡潔,但是該介面建立的 channel 只在觸發 timer 時才會釋放,另外 Local streamer 讀取事件是一個高頻呼叫,每次呼叫都建立一個 timer channel 開銷也較大。優化後改為複用 timer;

  • Relay 從上游讀取事件時使用了一個 timeout context,每次讀取都會建立一個額外的 channel,而在當前場景下,該 timeout context 並沒必要。優化後去掉了該 timeout context;

  • Relay reader、relay writer 寫入 debug 日誌未檢測 log level,每次都會建立一些 Field 物件,雖然不大,但是由於這些操作呼叫頻率較高,也會帶來一些開銷。優化後,對高頻呼叫的 debug 日誌,增加 log level 判斷。

    • 說明: DM 寫入日誌使用的 zap logger ,該 logger 效能較好,在非高頻呼叫下,直接呼叫 log.Debug 一般是沒問題的。

優化後的結果如下,可以看出 CPU 又降低了不少,尖刺也少了很多:

下圖為在 20 table 20 task 場景下的測試結果:

遺留問題 & 未來工作

經過上面的優化,開啟 relay 相比不開 relay,在 latency 上的差距已經很小, CPU 的增長也在一個相對低的水平,但是仍有一些點是可以繼續優化的,預期會在後續版本中逐步新增,如下:

  • go-mysql  讀檔案使用的  io.CopyN ,這個函式內部會申請一個小物件,高頻使用情況下還是對 GC 有一些影響的,但不大,這次暫時沒改;
  • 有些對  no relay  和  relay  同時生效的優化這次沒做,比如 streamer 讀取 event 時建立的 timeout context;
  • 目前看多個 reader 讀同一個檔案還是有不少開銷的,再優化的可能方案:

    • 減少讀的次數,比如一個 reader 讀完、其他的 reader 讀記憶體之類的,或者像之前設想的增加記憶體快取的方式;

    • 合併相同下游的 task,減少 task 數量。

:bulb: Tip: 上文標藍部分均有跳轉,由於微信外鏈限制,大家可以點選尾部 【閱讀原文】 檢視原文