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

前言

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 數量。