前言

說到MySQL的MTS，相信很多同學都不陌生，從5.6開始基于schema的并行回放，到5.7的LOGICAL_CLOCK支持基于事務的并行回放，這些內容都有文章講解，在本篇文章不再贅述。今天要講的是，你知道如何查看并行回放是否存在性能瓶頸嗎，是由于主庫事務行為導致無法并行回放，還是由于worker線程不足，限制了并行回放的天花板？這都得從一個Note信息說起。

MY-010559

在開啟了多線程回放的從庫error log，我們經常能看到Note級別的日志信息MY-010559

圖片

讓我們來看看這些日志的含義

Seconds elapsed：當前時間與上次輸出日志時間的間隔秒數

Events assigned：自slave協調線程啟動后，累計處理分發給worker線程的event數量。簡單理解為slave啟動后處理的event數量。

Worker queues filled over overrun level：worker線程處理的event隊列長度超過最大隊列數(目前代碼硬編碼16384)的90%的次數，如果0則說明未發生該情況。

Waited due to worker queue full：worker線程處理的event隊列長度達到最大(目前代碼硬編碼16384)的次數，如果為0則說明未發生該情況，是前面Worker queues filled over overrun level的情況升級。

Waited due to the total size：協調線程分發event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max限制而產生等待的次數。前面兩個參數是限制worker線程處理event隊列能夠申請的最大內存(即大事務)。如果遇到此種大事務，在回放該大事務之前，會等待其他worker線程處理完已分配event，然后再進行該大事務的回放，回放過程中，后續的event回放，也會進入等待狀態。總之，大事務回放特別影響并行回放的性能，只能串行回放。

Waited at clock conflicts：由于不能并行回放的累計等待時間，單位納秒。如果并行回放策略設置的是DATABASE而不是LOGICAL_CLOCK，該值一直為0。

Waited (count) when workers occupied：協調線程休眠次數。有兩種情況會累加此狀態值：1、worker線程達到最大隊列數(目前代碼硬編碼16384)的90%，此種情況協調線程最多休眠1毫秒；2、并行回放策略設置為LOGICAL_CLOCK時，由于沒有空閑的worker線程導致無法分配事務的第一個event而產生的等待，此種情況協調線程會一直處于等待狀態直到有空閑的worker線程能夠處理回放。

Waited when workers occupied：等待空閑的worker線程累計時間，單位納秒，對應Waited (count) when workers occupied的第二種等待情況。

代碼分析

在8.0.26版本的代碼中，我們通過錯誤信息關鍵字waited at clock conflicts查找，發現信息記錄在變量ER_RPL_MTS_STATISTICS中，

圖片

繼續按變量查找，發現其使用在rpl_replica.cc文件的apply_event_and_update_pos函數中，主要邏輯代碼如下

圖片

可以看到，滿足如下幾個條件，日志信息就會輸出

1. 并行回放為開啟狀態
2. 并行回放的累計event數量對1024取模余1
3. 當前時間減去上次日志時間間隔大于mts_online_stat_period(硬編碼120)秒
4. error log日志級別為info(log_error_verbosity=3)

上述幾個條件，和并行回放的事務繁忙程度并沒有太大的關系，滿足條件即會記錄日志。假如一個事務有4個event，參數設置正常，每兩分鐘執行256個事務，就會輸出一條日志信息，一秒鐘3個事務不到。

日志解析觀察

在我的日志文件中，取了如下兩條連續的信息

2023-07-09T08:58:01.001019+08:00 909 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'group_replication_applier': seconds elapsed = 180; events assigned = 11515905; worker queues filled over overrun level = 8314; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 136628031500 waited (count) when Workers occupied = 242457 waited when Workers occupied = 2223254351900
2023-07-09T09:00:01.648124+08:00 909 [Note] [MY-010559] [Repl] Multi-threaded slave statistics for channel 'group_replication_applier': seconds elapsed = 120; events assigned = 11518977; worker queues filled over overrun level = 8314; waited due a Worker queue full = 0; waited due the total size = 0; waited at clock conflicts = 136644607700 waited (count) when Workers occupied = 242491 waited when Workers occupied = 2223755727800

第一條解析信息如下：

. 本次日志輸出時間點為2023-07-09T08:58:01.001019
. 與上次日志輸出間隔時間為180秒
. 累計處理event數量為11515905
. worker線程處理的event隊列長度超過最大隊列數(目前代碼硬編碼16384)的90%的累計次數8314次
. worker線程處理的event隊列長度達到最大隊列數(目前代碼硬編碼16384)的累計次數為0次
. 回放event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次數為0
. 由于不能并行回放而產生的累計等待時間為136628031500納秒(約136.62秒)
. 協調線程累計休眠242457次
. 累計等待空閑worker線程的時間為2223254351900納秒(約2223.33秒)

第二條解析信息如下：

. 本次日志輸出時間點為2023-07-09T09:00:01.648124
. 與上次日志輸出間隔時間為120秒
. 累計處理event數量為11518977，新增處理event數量3072(為1024的3倍)
. worker線程處理的event隊列長度超過最大隊列數(目前代碼硬編碼16384)的90%的累計次數8314次，新增0次
. worker線程處理的event隊列長度達到最大隊列數(目前代碼硬編碼16384)的累計次數為0次
. 回放event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次數為0
. 由于不能并行回放而產生的累計等待時間為136644607700納秒(約136.64秒，新增等待約0.02秒)
. 協調線程累計休眠242457次，新增34次
. 累計等待空閑worker線程的時間為2223755727800納秒(約2223.38，新增等待約0.05秒)

通過上述信息，可以看出，在日志階段，系統處于空閑狀態，處理事務數不多。 對比各個參數，在系統繁忙時，因為不能并行回放產生的等待時間為136.64秒，等待空閑的worker線程累計時間為2223.38，因此增大slave_parallel_workers的參數值，可以提升并行回放性能。

總結

[Note] [MY-010559]在我剛開始接觸時，以為是系統出現了異常產生的日志，待真正了解其內容后，才發現通過該日志可以幫助我們了解MTS運行情況，針對性的做優化調整。

參考鏈接https://dev.mysql.com/doc/refman/8.0/en/replication-threads-monitor-worker.html