前言

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

MY-010559

在開(kāi)啟了多線程回放的從庫(kù)error log，我們經(jīng)常能看到Note級(jí)別的日志信息MY-010559

圖片

讓我們來(lái)看看這些日志的含義

Seconds elapsed：當(dāng)前時(shí)間與上次輸出日志時(shí)間的間隔秒數(shù)

Events assigned：自slave協(xié)調(diào)線程啟動(dòng)后，累計(jì)處理分發(fā)給worker線程的event數(shù)量。簡(jiǎn)單理解為slave啟動(dòng)后處理的event數(shù)量。

Worker queues filled over overrun level：worker線程處理的event隊(duì)列長(zhǎng)度超過(guò)最大隊(duì)列數(shù)(目前代碼硬編碼16384)的90%的次數(shù)，如果0則說(shuō)明未發(fā)生該情況。

Waited due to worker queue full：worker線程處理的event隊(duì)列長(zhǎng)度達(dá)到最大(目前代碼硬編碼16384)的次數(shù)，如果為0則說(shuō)明未發(fā)生該情況，是前面Worker queues filled over overrun level的情況升級(jí)。

Waited due to the total size：協(xié)調(diào)線程分發(fā)event大小達(dá)到replica_pending_jobs_size_max或者slave_pending_jobs_size_max限制而產(chǎn)生等待的次數(shù)。前面兩個(gè)參數(shù)是限制worker線程處理event隊(duì)列能夠申請(qǐng)的最大內(nèi)存(即大事務(wù))。如果遇到此種大事務(wù)，在回放該大事務(wù)之前，會(huì)等待其他worker線程處理完已分配event，然后再進(jìn)行該大事務(wù)的回放，回放過(guò)程中，后續(xù)的event回放，也會(huì)進(jìn)入等待狀態(tài)?？傊?，大事務(wù)回放特別影響并行回放的性能，只能串行回放。

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

Waited (count) when workers occupied：協(xié)調(diào)線程休眠次數(shù)。有兩種情況會(huì)累加此狀態(tài)值：1、worker線程達(dá)到最大隊(duì)列數(shù)(目前代碼硬編碼16384)的90%，此種情況協(xié)調(diào)線程最多休眠1毫秒；2、并行回放策略設(shè)置為L(zhǎng)OGICAL_CLOCK時(shí)，由于沒(méi)有空閑的worker線程導(dǎo)致無(wú)法分配事務(wù)的第一個(gè)event而產(chǎn)生的等待，此種情況協(xié)調(diào)線程會(huì)一直處于等待狀態(tài)直到有空閑的worker線程能夠處理回放。

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

代碼分析

在8.0.26版本的代碼中，我們通過(guò)錯(cuò)誤信息關(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ù)中，主要邏輯代碼如下

圖片

可以看到，滿足如下幾個(gè)條件，日志信息就會(huì)輸出

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

上述幾個(gè)條件，和并行回放的事務(wù)繁忙程度并沒(méi)有太大的關(guān)系，滿足條件即會(huì)記錄日志。假如一個(gè)事務(wù)有4個(gè)event，參數(shù)設(shè)置正常，每?jī)煞昼妶?zhí)行256個(gè)事務(wù)，就會(huì)輸出一條日志信息，一秒鐘3個(gè)事務(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

第一條解析信息如下：

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

第二條解析信息如下：

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

通過(guò)上述信息，可以看出，在日志階段，系統(tǒng)處于空閑狀態(tài)，處理事務(wù)數(shù)不多。 對(duì)比各個(gè)參數(shù)，在系統(tǒng)繁忙時(shí)，因?yàn)椴荒懿⑿谢胤女a(chǎn)生的等待時(shí)間為136.64秒，等待空閑的worker線程累計(jì)時(shí)間為2223.38，因此增大slave_parallel_workers的參數(shù)值，可以提升并行回放性能。

總結(jié)

[Note] [MY-010559]在我剛開(kāi)始接觸時(shí)，以為是系統(tǒng)出現(xiàn)了異常產(chǎn)生的日志，待真正了解其內(nèi)容后，才發(fā)現(xiàn)通過(guò)該日志可以幫助我們了解MTS運(yùn)行情況，針對(duì)性的做優(yōu)化調(diào)整。

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