Реплика MySQL отстаёт, Seconds_Behind_Source показывает 20 секунд, хотя в очереди одна транзакция, а после PURGE BINARY LOGS на источнике она вовсе перестаёт подключаться. Источник пишет изменения в бинлог при двухфазном коммите, реплика копирует его в relay log и применяет воркерами; позицию задаёт набор GTID, а не имя файла и смещение. Ниже на двух контейнерах: что делает SOURCE_AUTO_POSITION=1 и когда он упирается в очищенный бинлог, как число воркеров меняет время догонки, откуда берутся секунды лага и что делает полусинхронный коммит, когда реплика пропала. В PostgreSQL ту же работу делает walsender со слотом, а лаг измеряют четырьмя LSN (разбор).
Репликация MySQL: путь события и три измерения
Стенд
Источник и реплика — два контейнера в общей сети. После инициализации mysqld перезапускается один раз: дождись строки ready for connections ... port: 3306 в docker logs и только потом ходи в клиент.
N=dba-mysql-replication-binlog-gtid
docker network create $N-net
docker run -d --name $N-source --network $N-net --memory 1500m -e MYSQL_ROOT_PASSWORD=pg mysql:8.4 \
--server-id=1 --gtid-mode=ON --enforce-gtid-consistency=ON
docker run -d --name $N-replica --network $N-net --memory 1500m -e MYSQL_ROOT_PASSWORD=pg mysql:8.4 \
--server-id=2 --gtid-mode=ON --enforce-gtid-consistency=ON
s() { docker exec -i $N-source mysql -uroot -ppg -t "$@"; }
r() { docker exec -i $N-replica mysql -uroot -ppg -t "$@"; }
s -e "CREATE USER 'repl'@'%' IDENTIFIED BY 'pg'; GRANT REPLICATION SLAVE ON *.* TO 'repl'@'%';
CREATE DATABASE lab; CREATE TABLE lab.t (id int AUTO_INCREMENT PRIMARY KEY, v varchar(40), pad char(100));"
s -e "DELIMITER //
CREATE PROCEDURE lab.ins(n int) BEGIN DECLARE i int DEFAULT 0;
WHILE i < n DO INSERT INTO lab.t (v, pad) VALUES ('load', REPEAT('p', 100)); SET i = i + 1; END WHILE; END//
DELIMITER ;"
r -e "CHANGE REPLICATION SOURCE TO SOURCE_HOST='$N-source', SOURCE_USER='repl', SOURCE_PASSWORD='pg',
SOURCE_AUTO_POSITION=1, GET_SOURCE_PUBLIC_KEY=1; START REPLICA;"
r -e "SELECT version(), @@gtid_mode, @@binlog_format, @@sync_binlog, @@replica_parallel_type, @@replica_parallel_workers, @@replica_preserve_commit_order"+-----------+-------------+-----------------+---------------+-------------------------+----------------------------+---------------------------------+
| version() | @@gtid_mode | @@binlog_format | @@sync_binlog | @@replica_parallel_type | @@replica_parallel_workers | @@replica_preserve_commit_order |
+-----------+-------------+-----------------+---------------+-------------------------+----------------------------+---------------------------------+
| 8.4.13 | ON | ROW | 1 | LOGICAL_CLOCK | 4 | 1 |
+-----------+-------------+-----------------+---------------+-------------------------+----------------------------+---------------------------------+Версия сходится с тегом mysql-8.4.13. Бинлог в 8.4 включён по умолчанию. Реплика в 8.4 стартует с четырьмя воркерами и replica_preserve_commit_order=1: применяет параллельно, но фиксирует в порядке источника.
Опыт 1: позиция без имени файла
После INSERT INTO lab.t (v) VALUES ('one'),('two') на источнике реплика сообщает о равенстве наборов, а источник держит одну сессию Binlog Dump GTID:
r -e "SHOW REPLICA STATUS\G" | grep -E 'Retrieved|Executed|Seconds_Behind|Auto_Position'
s -e "SHOW PROCESSLIST" Seconds_Behind_Source: 0
Retrieved_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-10
Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-10,
Auto_Position: 1
| 12 | repl | 192.168.96.3:44390 | NULL | Binlog Dump GTID | 35 | Source has sent all binlog to replica; waiting for more updates |21e83b37-... — server_uuid источника, 1-10 — номера его транзакций. Реплика не говорит «дай с файла и позиции»: при подключении она присылает свой Executed_Gtid_Set, а источник сам находит файл. Проверка: остановить реплику, дважды записать с ротацией бинлога, удалить уже прочитанный файл и запустить снова.
r -e "STOP REPLICA"
s -e "INSERT INTO lab.t (v) VALUES ('five'); FLUSH BINARY LOGS; INSERT INTO lab.t (v) VALUES ('six'); FLUSH BINARY LOGS;
PURGE BINARY LOGS TO 'binlog.000004'; SHOW BINARY LOGS; SELECT @@global.gtid_executed, @@global.gtid_purged"
r -e "START REPLICA"
r -e "SHOW REPLICA STATUS\G" | grep -E 'Source_Log_File|Retrieved|Executed|Seconds_Behind'| binlog.000004 | 525 | No |
| binlog.000005 | 524 | No |
| binlog.000006 | 198 | No |
| 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-14 | 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-12 |
Source_Log_File: binlog.000006
Seconds_Behind_Source: 0
Retrieved_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:13-14
Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-14Реплика получила только транзакции 13-14 из двух разных файлов и не назвала ни одного имени файла (номера файлов подставь свои из SHOW BINARY LOGS). Обратный случай, из первого прогона опыта: источник удалил файл binlog.000002, в котором лежала транзакция 11, а реплика её ещё не получила (PURGE BINARY LOGS TO 'binlog.000003' при остановленной реплике). Источник отказывается её обслуживать, потому что gtid_purged не входит в присланный набор:
if (!gtid_state->get_lost_gtids()->is_subset(m_exclude_gtid)) {
mysql_bin_log.report_missing_purged_gtids(m_exclude_gtid, errmsg);
global_tsid_lock->unlock();
set_fatal_error(errmsg.c_str());
return 1;
}Строка Last_IO_Error реплики и предупреждение в логе источника:
Last_IO_Errno: 13114
Last_IO_Error: Got fatal error 1236 from source when reading data from binary log: 'Cannot replicate because the source purged required binary logs. Replicate the missing transactions from elsewhere, or provision a new replica from backup. Consider increasing the source's binary log expiration period. The GTID set sent by the replica is '21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-10,
22040867-d263-11f1-a1b9-beb537548d61:1-5', and the missing transactions are '21e83b37-d263-11f1-baaf-6eb01cc2b8c4:11''
2026-10-28T00:06:22.852861Z 18 [Warning] [MY-011809] [Server] Cannot replicate to server with server_uuid='22040867-d263-11f1-a1b9-beb537548d61' because the present server has purged required binary logs. The connecting server needs to replicate the missing transactions from elsewhere, or be replaced by a new server created from a more recent backup. To prevent this error in the future, consider increasing the binary log expiration period on the present server. The missing transactions are '21e83b37-d263-11f1-baaf-6eb01cc2b8c4:11'.Сообщение называет недостающую транзакцию: :11. Вторая UUID в присланном наборе — собственные 5 транзакций реплики, выполненные до подключения. Повторный START REPLICA ничего не изменит: этот бинлог источник уже не вернёт. Реплику в опыте пришлось пересобрать: STOP REPLICA; RESET REPLICA ALL, снять mysqldump --databases lab --set-gtid-purged=ON --single-transaction с источника, загрузить его в реплику после RESET BINARY LOGS AND GTIDS и снова CHANGE REPLICATION SOURCE ...; Executed_Gtid_Set реплики после загрузки стал 1-12.
Опыт 2: догонка бэклога при 1 и 4 воркерах
Чтобы получить лаг без подбора скорости, останови SQL-поток реплики, дай источнику 8000 коммитов с восьми клиентов, потом запусти SQL-поток и замерь, за сколько реплика применит всё. Ожидание конца — WAIT_FOR_EXECUTED_GTID_SET с набором источника.
r -e "STOP REPLICA SQL_THREAD; SET GLOBAL replica_parallel_workers=4" # или 1
for i in 1 2 3 4 5 6 7 8; do s -e "CALL lab.ins(1000)" & done; wait
G=$(docker exec $N-source mysql -uroot -ppg -N -e "SELECT @@global.gtid_executed" 2>/dev/null | tr -d '\n')
r -e "START REPLICA SQL_THREAD"
time r -N -e "SELECT WAIT_FOR_EXECUTED_GTID_SET('$G', 600)"Шесть прогонов на конфигурацию, источник принимал 8000 коммитов за 4,0–8,8 с. Время ожидания в секундах, по порядку прогонов:
workers=1: 24.4 24.4 22.3 19.8 21.6 20.1
workers=4: 10.5 6.7 10.1 7.1 8.4 11.4
workers=2: 13.2 (один прогон)Медиана: 22,0 с при одном воркере и 9,3 с при четырёх, то есть в 2,4 раза быстрее, но не в 4 раза, а разброс при четырёх воркерах шире (6,7–11,4 против 19,8–24,4). Два прогона (22.3 и 10.1) шли с опросом статуса раз в секунду. Параллельно реплика применяет только транзакции, закоммиченные на источнике одновременно (replica_parallel_type=LOGICAL_CLOCK); сколько таких в этой нагрузке, опыт не измерял: в образе нет mysqlbinlog. Seconds_Behind_Source, который опрашивался раз в секунду в тех же двух прогонах, ведёт себя по-разному:
workers=1
0.0 s: Seconds_Behind_Source: 7 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-48027
22.1 s: Seconds_Behind_Source: 24 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-55959
23.2 s: Seconds_Behind_Source: 0 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-56015
workers=4
0.0 s: Seconds_Behind_Source: 13 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-40066
4.3 s: Seconds_Behind_Source: 8 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-44121
9.6 s: Seconds_Behind_Source: 12 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-47710
10.6 s: Seconds_Behind_Source: 0 Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-48015При одном воркере число растёт с 7 до 24, пока набор GTID движется: события старше ровно настолько, насколько реплика медленнее источника. При четырёх оно идёт 13, 8, 12 и только в конце 0 и не отражает, сколько осталось. Формула в коде — разность часов и метки времени события:
long time_diff = ((long)(time(nullptr) - mi->rli->last_master_timestamp) -
mi->clock_diff_with_master);
...
protocol->store(
(longlong)(mi->rli->last_master_timestamp ? max(0L, time_diff) : 0));Строки 3599–3600 и 3621–3622: в формуле только time(nullptr) - last_master_timestamp, ни байтов, ни числа транзакций. Для параллельного применения метка обновляется, по комментарию кода (строки 4941–4945), когда задание уходит из очереди воркеров, а не когда его читает координатор.
Опыт 3: 20 секунд лага на одну транзакцию
Если секунды считаются по возрасту события, одна застрявшая транзакция даёт любой лаг. На реплике открывается транзакция, блокирующая строку 1; на источнике строка обновляется:
docker exec -d $N-replica mysql -uroot -ppg -e "BEGIN; SELECT id FROM lab.t WHERE id=1 FOR UPDATE; DO SLEEP(22); ROLLBACK"
s -e "UPDATE lab.t SET v='locked' WHERE id=1"
r -e "SHOW REPLICA STATUS\G" | grep -E 'Seconds_Behind|Retrieved_Gtid|Executed_Gtid|SQL_Running_State' # через 5 и 20 с
r -e "SELECT WORKER_ID, APPLYING_TRANSACTION, APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP FROM performance_schema.replication_applier_status_by_worker WHERE APPLYING_TRANSACTION<>''"--- 5 s
Seconds_Behind_Source: 5
Replica_SQL_Running_State: Replica has read all relay log; waiting for more updates
Retrieved_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:13-104016
Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-104015
--- 20 s
Seconds_Behind_Source: 20
Replica_SQL_Running_State: Replica has read all relay log; waiting for more updates
Retrieved_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:13-104016
Executed_Gtid_Set: 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:1-104015
+-----------+---------------------------------------------+------------------------------------------------+
| WORKER_ID | APPLYING_TRANSACTION | APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP |
+-----------+---------------------------------------------+------------------------------------------------+
| 1 | 21e83b37-d263-11f1-baaf-6eb01cc2b8c4:104016 | 2026-10-28 00:14:03.483887 |
+-----------+---------------------------------------------+------------------------------------------------+Лаг растёт на секунду в секунду (5, 10, 15, 20), хотя Retrieved и Executed различаются ровно на одну транзакцию, 104016. Состояние SQL-потока при этом утверждает, что весь relay log прочитан: оно описывает чтение, а не применение. После ROLLBACK на реплике транзакция применилась и Seconds_Behind_Source вернулся к 0. Обратная сторона: пока IO-поток не работает, поле равно NULL, а не 0 (так было и после ошибки 1236, и после STOP REPLICA IO_THREAD), и алерт «лаг больше N секунд» молчит именно тогда, когда реплика сломана.
Опыт 4: полусинхронная репликация, AFTER_SYNC
В 8.4 полусинхронная репликация — плагины semisync_source.so на источнике и semisync_replica.so на реплике. Включение, таймаут 5000 мс вместо 10 000 по умолчанию и перезапуск IO-потока, чтобы реплика зарегистрировалась как полусинхронная:
s -e "INSTALL PLUGIN rpl_semi_sync_source SONAME 'semisync_source.so'; SET GLOBAL rpl_semi_sync_source_enabled=1;
SET GLOBAL rpl_semi_sync_source_timeout=5000;
SELECT @@rpl_semi_sync_source_wait_point, @@rpl_semi_sync_source_timeout, @@rpl_semi_sync_source_wait_for_replica_count"
r -e "INSTALL PLUGIN rpl_semi_sync_replica SONAME 'semisync_replica.so'; SET GLOBAL rpl_semi_sync_replica_enabled=1;
STOP REPLICA IO_THREAD; START REPLICA IO_THREAD"+-----------------------------------+--------------------------------+-----------------------------------------------+
| @@rpl_semi_sync_source_wait_point | @@rpl_semi_sync_source_timeout | @@rpl_semi_sync_source_wait_for_replica_count |
+-----------------------------------+--------------------------------+-----------------------------------------------+
| AFTER_SYNC | 5000 | 1 |
+-----------------------------------+--------------------------------+-----------------------------------------------+Точка ожидания — AFTER_SYNC: плагин ждёт ack в хуке после записи бинлога, до коммита в InnoDB (semisync_source_plugin.cc, строки 96–101, функция repl_semi_report_binlog_sync). Сам ожидатель — ReplSemiSyncMaster::commitTrx; вот его ветка таймаута:
if (wait_result != 0) {
/* This is a real wait timeout. */
LogErr(WARNING_LEVEL, ER_SEMISYNC_WAIT_FOR_BINLOG_TIMEDOUT,
trx_wait_binlog_name, (unsigned long)trx_wait_binlog_pos,
reply_file_name_, (unsigned long)reply_file_pos_);
rpl_semi_sync_source_wait_timeouts++;
/* switch semi-sync off */
switch_off();
} else {Теперь останови реплику и закоммить, пока вторая сессия смотрит со стороны:
r -e "STOP REPLICA"
docker exec -d $N-source mysql -uroot -ppg -e "INSERT INTO lab.t (v) VALUES ('semi-wait')"
s -e "SELECT count(*) AS cnt_seen_by_other_session FROM lab.t WHERE v='semi-wait';
SELECT ID, STATE, LEFT(INFO,50) INFO FROM information_schema.PROCESSLIST WHERE STATE LIKE '%semi%'"
sleep 5; s -e "SELECT count(*) FROM lab.t WHERE v='semi-wait'"
s -e "SHOW STATUS WHERE Variable_name IN ('Rpl_semi_sync_source_status','Rpl_semi_sync_source_yes_tx','Rpl_semi_sync_source_no_tx','Rpl_semi_sync_source_clients')"+---------------------------+
| cnt_seen_by_other_session |
+---------------------------+
| 0 |
+---------------------------+
+-----+----------------------------------------+--------------------------------------------+
| ID | STATE | INFO |
+-----+----------------------------------------+--------------------------------------------+
| 154 | Waiting for semi-sync ACK from replica | INSERT INTO lab.t (v) VALUES ('semi-wait') |
+-----+----------------------------------------+--------------------------------------------+
+----------+
| count(*) |
+----------+
| 1 |
+----------+
| Rpl_semi_sync_source_clients | 1 |
| Rpl_semi_sync_source_no_tx | 1 |
| Rpl_semi_sync_source_status | OFF |
| Rpl_semi_sync_source_yes_tx | 1 |Пока коммит ждёт, другая сессия строки не видит (0), потому что ждёт он до коммита в InnoDB. По таймауту транзакция не откатывается: через 5 секунд строка есть, Rpl_semi_sync_source_status стал OFF, а no_tx (коммиты без ack) вырос до 1. Время двух подряд коммитов (TIMESTAMPDIFF вокруг INSERT, реплика остановлена) и запись в логе источника из повторного прогона:
+-----------+
| ms |
+-----------+
| 5002.6410 |
+-----------+
+--------+
| ms |
+--------+
| 2.3360 |
+--------+
2026-10-28T00:15:53.123370Z 161 [Warning] [MY-011153] [Repl] Timeout waiting for reply of binlog (file: binlog.000006, pos: 41518030), semi-sync up to file binlog.000006, position 41517740.Коммит продержался 5002,6 мс, следующий в режиме OFF занял 2,3 мс: источник перешёл на асинхронную репликацию и молча продолжил. Предупреждение в логе — единственный след, кроме счётчиков. После START REPLICA статус вернулся в ON сам. Цена ack при здоровой реплике в одной сети контейнеров мала: Rpl_semi_sync_source_tx_avg_wait_time = 208 мкс, а 1000 коммитов одним клиентом заняли 3612 и 3501 мс с плагином против 3453 и 3466 мс без него (rpl_semi_sync_source_enabled=1 и 0 по очереди). На реальной сети к этому добавится её RTT. PostgreSQL при синхронной репликации по документации тоже ждёт подтверждения на каждом коммите, но таймаута у него нет: без живой реплики коммит висит, пока её не уберут из списка (опыт). MySQL выбирает доступность, PostgreSQL — гарантию.
Group Replication
Group Replication в опыте не участвовала. По коду: плагин лежит в plugin/group_replication/, а консенсус — это XCom, собственная реализация Paxos в plugin/group_replication/libmysqlgcs/src/bindings/xcom/xcom/xcom_base.cc (автомат paxos_fsm, строка 9380).
Что из этого следует
SOURCE_AUTO_POSITION=1избавляет от файла и позиции, но не от срока хранения бинлога. Реплика, которой нужна уже удалённая транзакция, получает ошибку 1236 и требует пересборки. Срок хранения (binlog_expire_logs_seconds) должен покрывать самый долгий допустимый простой реплики.- Воркеры помогают, пока источник коммитит параллельно. Четыре воркера сократили медиану догонки с 22,0 до 9,3 с на нагрузке из восьми клиентов.
Seconds_Behind_Source— возраст события, не размер очереди. Алерт по нему ловит застрявшую транзакцию и ничего не знает о том, сколько ещё осталось. Для объёма сравнивайGTID_SUBTRACT(<gtid_executed источника>, <gtid_executed реплики>).- Полусинхронный режим не гарантирует, что ack получен. При таймауте источник сам переходит в асинхронный режим; единственные следы —
Rpl_semi_sync_source_status = OFFи предупреждение в логе. Следи за статусом и счётчикомno_tx, а не за самим плагином.
Чек-лист
- На реплике
SHOW REPLICA STATUS\G:Retrieved_Gtid_SetиExecuted_Gtid_Setдолжны совпадать; если нет, смотриreplication_applier_status_by_worker. - Не опирайся на
Seconds_Behind_Sourceкак на единственный сигнал: добавь сравнение GTID-наборов источника и реплики и алерт наNULL. - Проверь
binlog_expire_logs_secondsпротив самого долгого простоя реплики; послеPURGE BINARY LOGSсверьgtid_purgedсExecuted_Gtid_Setреплики. - Для полусинхронной репликации заведи алерт на
Rpl_semi_sync_source_status != ON. - Убери стенд:
docker rm -f -v $N-source $N-replica; docker network rm $N-net.