建站
咨詢
售后
建站咨詢
新聞中心
前言
說到MySQL的MTS，相信很多同學(xué)都不陌生，從5.6開始基于schema的并行回放，到5.7的LOGICAL_CLOCK支持基于事務(wù)的并行回放，這些內(nèi)容都有文章講解，在本篇文章不再贅述。今天要講的是，你知道如何查看并行回放是否存在性能瓶頸嗎，是由于主庫事務(wù)行為導(dǎo)致無法并行回放，還是由于worker線程不足，限制了并行回放的天花板？這都得從一個Note信息說起。
為獨山等地區(qū)用戶提供了全套網(wǎng)頁設(shè)計制作服務(wù)，及獨山網(wǎng)站建設(shè)行業(yè)解決方案。主營業(yè)務(wù)為成都網(wǎng)站設(shè)計、成都網(wǎng)站制作、獨山網(wǎng)站設(shè)計，以傳統(tǒng)方式定制建設(shè)網(wǎng)站，并提供域名空間備案等一條龍服務(wù)，秉承以專業(yè)、用心的態(tài)度為用戶提供真誠的服務(wù)。我們深信只要達到每一位用戶的要求，就會得到認可，從而選擇與我們長期合作。這樣，我們也可以走得更遠！
MY-010559
在開啟了多線程回放的從庫error log，我們經(jīng)常能看到Note級別的日志信息MY-010559
圖片
讓我們來看看這些日志的含義
Seconds elapsed：當前時間與上次輸出日志時間的間隔秒數(shù)
Events assigned：自slave協(xié)調(diào)線程啟動后，累計處理分發(fā)給worker線程的event數(shù)量。簡單理解為slave啟動后處理的event數(shù)量。
Worker queues filled over overrun level：worker線程處理的event隊列長度超過最大隊列數(shù)(目前代碼硬編碼16384)的90%的次數(shù)，如果0則說明未發(fā)生該情況。
Waited due to worker queue full：worker線程處理的event隊列長度達到最大(目前代碼硬編碼16384)的次數(shù)，如果為0則說明未發(fā)生該情況，是前面Worker queues filled over overrun level的情況升級。
Waited due to the total size：協(xié)調(diào)線程分發(fā)event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max限制而產(chǎn)生等待的次數(shù)。前面兩個參數(shù)是限制worker線程處理event隊列能夠申請的最大內(nèi)存(即大事務(wù))。如果遇到此種大事務(wù)，在回放該大事務(wù)之前，會等待其他worker線程處理完已分配event，然后再進行該大事務(wù)的回放，回放過程中，后續(xù)的event回放，也會進入等待狀態(tài)?？傊笫聞?wù)回放特別影響并行回放的性能，只能串行回放。
Waited at clock conflicts：由于不能并行回放的累計等待時間，單位納秒。如果并行回放策略設(shè)置的是DATABASE而不是LOGICAL_CLOCK，該值一直為0。
Waited (count) when workers occupied：協(xié)調(diào)線程休眠次數(shù)。有兩種情況會累加此狀態(tài)值：1、worker線程達到最大隊列數(shù)(目前代碼硬編碼16384)的90%，此種情況協(xié)調(diào)線程最多休眠1毫秒；2、并行回放策略設(shè)置為LOGICAL_CLOCK時，由于沒有空閑的worker線程導(dǎo)致無法分配事務(wù)的第一個event而產(chǎn)生的等待，此種情況協(xié)調(diào)線程會一直處于等待狀態(tài)直到有空閑的worker線程能夠處理回放。
Waited when workers occupied：等待空閑的worker線程累計時間，單位納秒，對應(yīng)Waited (count) when workers occupied的第二種等待情況。
代碼分析
在8.0.26版本的代碼中，我們通過錯誤信息關(guān)鍵字waited at clock conflicts查找，發(fā)現(xiàn)信息記錄在變量ER_RPL_MTS_STATISTICS中，
圖片
繼續(xù)按變量查找，發(fā)現(xiàn)其使用在rpl_replica.cc文件的apply_event_and_update_pos函數(shù)中，主要邏輯代碼如下
圖片
可以看到，滿足如下幾個條件，日志信息就會輸出
- 并行回放為開啟狀態(tài)
- 并行回放的累計event數(shù)量對1024取模余1
- 當前時間減去上次日志時間間隔大于mts_online_stat_period(硬編碼120)秒
- error log日志級別為info(log_error_verbosity=3)
上述幾個條件，和并行回放的事務(wù)繁忙程度并沒有太大的關(guān)系，滿足條件即會記錄日志。假如一個事務(wù)有4個event，參數(shù)設(shè)置正常，每兩分鐘執(zhí)行256個事務(wù)，就會輸出一條日志信息，一秒鐘3個事務(wù)不到。
日志解析觀察
在我的日志文件中，取了如下兩條連續(xù)的信息
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數(shù)量為11515905
. worker線程處理的event隊列長度超過最大隊列數(shù)(目前代碼硬編碼16384)的90%的累計次數(shù)8314次
. worker線程處理的event隊列長度達到最大隊列數(shù)(目前代碼硬編碼16384)的累計次數(shù)為0次
. 回放event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次數(shù)為0
. 由于不能并行回放而產(chǎn)生的累計等待時間為136628031500納秒(約136.62秒)
. 協(xié)調(diào)線程累計休眠242457次
. 累計等待空閑worker線程的時間為2223254351900納秒(約2223.33秒)第二條解析信息如下：
. 本次日志輸出時間點為2023-07-09T09:00:01.648124
. 與上次日志輸出間隔時間為120秒
. 累計處理event數(shù)量為11518977，新增處理event數(shù)量3072(為1024的3倍)
. worker線程處理的event隊列長度超過最大隊列數(shù)(目前代碼硬編碼16384)的90%的累計次數(shù)8314次，新增0次
. worker線程處理的event隊列長度達到最大隊列數(shù)(目前代碼硬編碼16384)的累計次數(shù)為0次
. 回放event大小達到replica_pending_jobs_size_max或者slave_pending_jobs_size_max的次數(shù)為0
. 由于不能并行回放而產(chǎn)生的累計等待時間為136644607700納秒(約136.64秒，新增等待約0.02秒)
. 協(xié)調(diào)線程累計休眠242457次，新增34次
. 累計等待空閑worker線程的時間為2223755727800納秒(約2223.38，新增等待約0.05秒)通過上述信息，可以看出，在日志階段，系統(tǒng)處于空閑狀態(tài)，處理事務(wù)數(shù)不多。 對比各個參數(shù)，在系統(tǒng)繁忙時，因為不能并行回放產(chǎn)生的等待時間為136.64秒，等待空閑的worker線程累計時間為2223.38，因此增大slave_parallel_workers的參數(shù)值，可以提升并行回放性能。
總結(jié)
[Note] [MY-010559]在我剛開始接觸時，以為是系統(tǒng)出現(xiàn)了異常產(chǎn)生的日志，待真正了解其內(nèi)容后，才發(fā)現(xiàn)通過該日志可以幫助我們了解MTS運行情況，針對性的做優(yōu)化調(diào)整。
參考鏈接https://dev.mysql.com/doc/refman/8.0/en/replication-threads-monitor-worker.html
分享標題：MTS性能監(jiān)控你知道多少
路徑分享：http://www.5511xx.com/article/dhocjcd.html
