Имеется AWS
Seconds_Behind_Master
.
Ниже — попытки разобраться в причинах и исправить ситуацию.
Забегая наперёд — причину нашёл, однако решения как избежать её в будущем не искал, а «пофиксилось» путём запуска нового read-replica сервера, но на будущее оставлю себе запись о том, как проверял статус и искал решение.
Содержание
Проблема
Если в пятницу значение Seconds_Behind_Master
было:
Seconds_Behind_Master: 112144
То в понедельник — уже:
Seconds_Behind_Master: 352097
Сама проблема возникла в четверг, после выполнения запроса на alter collation одной таблицы.
Кроме того — в CloudWatch доступны метрики, которые могут показать статус реликации.
ReplicaLag
на реплике:
BinLogDiskUsage
на мастере:
Полезные значения в slave status
Немного рассмотрим вывод SHOW 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, так что создать новую реплику не проблема.
Создаём новую реплику и проверим статус слейва:
Вот теперь с репликацией всё хорошо.
Рестарт старой реплики
Возвращаемся к старой реплике.
Переключаем клиентов на новую реплику, и пробуем рестартануть слейв на старой:
Проверяем SHOW PROCESSLIST
И вот только сейчас я обратил внимание на запрос:
Тут 360504 — это время его «выполнения». Тот самый запрос, который висит с четверга и на котором «повесилась» репликация.
Вывод — проблемы с репликой надо решать с проверки процессов.
А тем временем — рестарт реплики не работает, запрос тоже завис:
Уже 2021 секунд.
Хорошо — пробуем убить процесс, который завис на локе:
Ну, ок…
Ребутаем инстанс:
После рестарта проверяем процессы:
И после ребута — «упс»?:
Перед этим я запускал mysql.rds_stop_replication
Зато — логи, позиции и время отставания от мастера «выровнялись»:
Попробуем запустить:
Но 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
Ага, и в консоли есть сообщение:
Только же оно не помогает…
И это же сообщение есть в последних событиях:
Но слейв не стартует. И в логах ошибок нет…
Есть предположение, что на мастере нет бинлога, который пытается читать слейв:
Если так — то можно было бы выполнить
mysql.rds_reset_external_master
С другой стороны — по идее тогда должна была бы быть ошибка при старте Slave_IO
— но ничего нет.
В любом случае, раз запущен новый read-replica сервер — то можно на эту проблему уже забить, т.к. времени разбираться нет, ибо ждут другие задачи.
P.S. Нет — бинлог на мастере таки есть, проверяем с помощью SHOW MASTER LOGS
:
Так что почему call mysql.mysql.rds_start_replication
не стартует репликацию — пока загадка.