Имеется AWS сервер, у котого постоянно растёт значение Seconds_Behind_Master.
Ниже – попытки разобраться в причинах и исправить ситуацию.
Забегая наперёд – причину нашёл, однако решения как избежать её в будущем не искал, а “пофиксилось” путём запуска нового read-replica сервера, но на будущее оставлю себе запись о том, как проверял статус и искал решение.
Проблема
Если в пятницу значение Seconds_Behind_Master было:
Seconds_Behind_Master: 112144
То в понедельник – уже:
Seconds_Behind_Master: 352097
Сама проблема возникла в четверг, после выполнения запроса на alter collation одной таблицы.
Кроме того – в CloudWatch доступны метрики, которые могут показать статус реликации.
ReplicaLag на реплике:
BinLogDiskUsage на мастере:
Полезные значения в slave status
Немного рассмотрим вывод .
Нас интересуют следующие значения:
Master_Log_File– binlog на мастере, который сейчас читается на слейвеRead_Master_Log_Pos– позиция в нём
Relay_Master_Log_File– файл репликации, из которого было выполнено последняя успешная репликация на слейвеExec_Master_Log_Pos– позиция последнего успешного действия изRelay_Master_Log_File
Что мы видим тут: на мастере сейчас пишется лог mysql-bin-changelog.042263, в позицию 859993.
На слейве – выполняются действия из лога mysql-bin-changelog.041073, позиция 431032 – налицо явное отставание в выполнении репликации.
Более того – если проверить операции записи на диск на реплике, то явно видно что с четверга, когда был выполнен ALTER TABLE запрос и с которого началась проблема – на слейве практически не выполняются операции по записи на диск, т.е. база по сути не обновляется:
А в SHOW SLAVE STATUS в Slave_IO_State постоянно значение Waiting for master to send event.
Кроме того – обратим внимание на Relay_Log_Pos и Exec_Master_Log_Pos – их значение не меняется от слова совсем.
Stop-Start slave
Первым решением было бы просто перезапустить воркеры репликации:
- IO Thread : Responsible for Maintaining a Connection Back to the Master. It is used to collect SQL entries recorded in the Master’s Binary Logs and storing those entries in the Slave’s Relay Logs.
- SQL Thread : Responsible for Reading the Entries from the Slave’s Local Relay Logs, Executing the SQL, and Rotating the Fully Used Relay Logs.
Но тут RDS приподносит сюрприз:
Это ограничение RDS, и вместо стандартного stop/start – используем готовые процедуры, см. описание и документацию .
Процедуру можно посмотреть с помощью:
Т.к. реплика сейчас используется, то есть ещё одно решение – просто создать новую реплику, переключить клиентов на неё, а потом уже вызывать эту процедуру (и это оказалось правильным решением).
Пересоздание read-replica сервера
Перед созданием реплики – убедитесь, что нет MyISAM таблиц (см. Preparing MySQL DB Instances That Use MyISAM в ):
У нас всё в InnoDB, так что создать новую реплику не проблема.
Создаём новую реплику и проверим статус слейва:
Вот теперь с репликацией всё хорошо.
Рестарт старой реплики
Возвращаемся к старой реплике.
Переключаем клиентов на новую реплику, и пробуем рестартануть слейв на старой:
Проверяем :
И вот только сейчас я обратил внимание на запрос:
Тут 360504 – это время его “выполнения”. Тот самый запрос, который висит с четверга и на котором “повесилась” репликация.
Вывод – проблемы с репликой надо решать с проверки процессов.
А тем временем – рестарт реплики не работает, запрос тоже завис:
Уже 2021 секунд.
Хорошо – пробуем убить процесс, который завис на локе:
Ну, ок…
Ребутаем инстанс:
После рестарта проверяем процессы:
И после ребута – “упс”?:
Перед этим я запускал – может потому реплика не запустилась?
Зато – логи, позиции и время отставания от мастера “выровнялись”:
Попробуем запустить:
Но cтатус Slave_IO_Running и Slave_SQL_Running всё-равно No…
Что в логах?
Есть сообщение об остановке обоих воркеров:
2018-07-09 11:48:42 47993326864128 [Note] Slave SQL thread exiting, replication stopped in log ‘mysql-bin-changelog.041073’ at position 431233; GTID position ‘0-11889406-202590637’
2018-07-09 11:48:42 47993326597888 [Note] Slave I/O thread exiting, read up to log ‘mysql-bin-changelog.042290’, position 991022; GTID position 0-11889406-206808121
И вроде всё хорошо после запуска:
…
2018-07-09 11:48:57 47747421896384 [Note] Reading of all Master_info entries succeded
2018-07-09 11:48:57 47747421896384 [Note] Added new Master_info ” to hash table
2018-07-09 11:48:57 47747421896384 [Warning] Recovery from master pos 431233 and file mysql-bin-changelog.041073.
2018-07-09 11:48:57 47747421896384 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections.
Version: ‘10.2.11-MariaDB’ socket: ‘/tmp/mysql.sock’ port: 3306 MariaDB Server
2018-07-09 11:51:21 47761961555712 [Note] InnoDB: Buffer pool(s) load completed at 180709 11:51:21
Ага, и в консоли есть сообщение:
Только же оно не помогает…
И это же сообщение есть в последних событиях:
Но слейв не стартует. И в логах ошибок нет…
Есть предположение, что на мастере нет бинлога, который пытается читать слейв:
Если так – то можно было бы выполнить , и обновить имя файла.
С другой стороны – по идее тогда должна была бы быть ошибка при старте Slave_IO – но ничего нет.
В любом случае, раз запущен новый read-replica сервер – то можно на эту проблему уже забить, т.к. времени разбираться нет, ибо ждут другие задачи.
P.S. Нет – бинлог на мастере таки есть, проверяем с помощью SHOW MASTER LOGS:
Так что почему call mysql.mysql.rds_start_replication не стартует репликацию – пока загадка.
