MariaDB: AWS RDS read-replica и Seconds_Behind

Имеется AWS RDS read-replica сервер, у котого постоянно растёт значение 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: mysql-bin-changelog.042263

Read_Master_Log_Pos: 859993

Master_Log_File — binlog на мастере, который сейчас читается на слейве
Read_Master_Log_Pos — позиция в нём

Relay_Master_Log_File: mysql-bin-changelog.041073

Exec_Master_Log_Pos: 431032

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 приподносит сюрприз:

MariaDB [dbname]> stop slave;

ERROR 1045 (28000): Access denied for user 'root'@'%' (using password: YES)

Это ограничение RDS, и вместо стандартного stop/start — используем готовые процедуры, см. описание тут>>> и документацию тут>>>.

Процедуру можно посмотреть с помощью:

MariaDB [dbname]> SHOW CREATE PROCEDURE mysql.rds_stop_replication;

Т.к. реплика сейчас используется, то есть ещё одно решение — просто создать новую реплику, переключить клиентов на неё, а потом уже вызывать эту процедуру (и это оказалось правильным решением).

Пересоздание read-replica сервера

Перед созданием реплики — убедитесь, что нет MyISAM таблиц (см. Preparing MySQL DB Instances That Use MyISAM в документации>>>):

MariaDB [dbname]> SELECT TABLE_NAME, ENGINE FROM information_schema.TABLES where TABLE_SCHEMA = 'dbname';
+-------------------------+--------+
| TABLE_NAME              | ENGINE |
+-------------------------+--------+
| activity_types          | InnoDB |
| admins                  | InnoDB |
...

У нас всё в InnoDB, так что создать новую реплику не проблема.

Создаём новую реплику и проверим статус слейва:

Master_Log_File: mysql-bin-changelog.042279
Read_Master_Log_Pos: 1180404
...
Relay_Master_Log_File: mysql-bin-changelog.042279
...
Exec_Master_Log_Pos: 1180404

Вот теперь с репликацией всё хорошо.

Рестарт старой реплики

Возвращаемся к старой реплике.

Переключаем клиентов на новую реплику, и пробуем рестартануть слейв на старой:

MariaDB [dbname]> CALL mysql.rds_stop_replication;

Проверяем SHOW PROCESSLIST:

...
| 362939 | rdsadmin    | localhost:36930      | mysql     | Query     |      171 | Killing slave                    | STOP SLAVE                                                                                           |    0.000 |
...

И вот только сейчас я обратил внимание на запрос:

Тут 360504 — это время его «выполнения». Тот самый запрос, который висит с четверга и на котором «повесилась» репликация.

Вывод — проблемы с репликой надо решать с проверки процессов.

А тем временем — рестарт реплики не работает, запрос тоже завис:

...
|  362939 | rdsadmin    | localhost:36930      | mysql     | Query     |     2021 | Killing slave                    | STOP SLAVE                                                                                           |    0.000 |
...

Уже 2021 секунд.

Хорошо — пробуем убить процесс, который завис на локе:

MariaDB [(none)]> kill 11;

ERROR 1095 (HY000): You are not owner of thread 11

Ну, ок…

Ребутаем инстанс:

После рестарта проверяем процессы:

MariaDB [dbname]> show processlist;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    10
Current database: dbname
+----+-------------+----------------------+-----------+---------+------+--------------------------+------------------+----------+
| Id | User        | Host                 | db        | Command | Time | State                    | Info             | Progress |
+----+-------------+----------------------+-----------+---------+------+--------------------------+------------------+----------+
|  3 | system user |                      | NULL      | Daemon  | NULL | InnoDB purge worker      | NULL             |    0.000 |
|  2 | system user |                      | NULL      | Daemon  | NULL | InnoDB purge worker      | NULL             |    0.000 |
|  1 | system user |                      | NULL      | Daemon  | NULL | InnoDB purge coordinator | NULL             |    0.000 |
|  4 | system user |                      | NULL      | Daemon  | NULL | InnoDB purge worker      | NULL             |    0.000 |
|  5 | system user |                      | NULL      | Daemon  | NULL | InnoDB shutdown handler  | NULL             |    0.000 |
|  8 | rdsadmin    | localhost:44727      | NULL      | Sleep   |    8 |                          | NULL             |    0.000 |
| 10 | root        | 194.***.***.26:42318 | dbname    | Query   |    0 | init                     | show processlist |    0.000 |
+----+-------------+----------------------+-----------+---------+------+--------------------------+------------------+----------+

И после ребута — «упс»?:

...
Slave_IO_Running: No
Slave_SQL_Running: No
...

Перед этим я запускал mysql.rds_stop_replication — может потому реплика не запустилась?

Зато — логи, позиции и время отставания от мастера «выровнялись»:

...
Master_Log_File: mysql-bin-changelog.041073
Read_Master_Log_Pos: 431233
Relay_Master_Log_File: mysql-bin-changelog.041073
Exec_Master_Log_Pos: 431233
Seconds_Behind_Master: NULL
...

Попробуем запустить:

MariaDB [dbname]> CALL mysql.rds_start_replication;

Query OK, 0 rows affected (0.29 sec)

Но 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

Ага, и в консоли есть сообщение:

Только же оно не помогает…

И это же сообщение есть в последних событиях:

Но слейв не стартует. И в логах ошибок нет…

Есть предположение, что на мастере нет бинлога, который пытается читать слейв:

…
Master_Log_File: mysql-bin-changelog.041073
…

Если так — то можно было бы выполнить mysql.rds_reset_external_master, и обновить имя файла.

С другой стороны — по идее тогда должна была бы быть ошибка при старте Slave_IO — но ничего нет.

В любом случае, раз запущен новый read-replica сервер — то можно на эту проблему уже забить, т.к. времени разбираться нет, ибо ждут другие задачи.

P.S. Нет — бинлог на мастере таки есть, проверяем с помощью SHOW MASTER LOGS:

Log_name        File_size
mysql-bin-changelog.041072      1211113
mysql-bin-changelog.041073      839363
...

Так что почему call mysql.mysql.rds_start_replication не стартует репликацию — пока загадка.

Ссылки по теме

How to Fix a Lagging MySQL Replication

Solving MySQL Replication Lag with LOGICAL_CLOCK and Calibrated Delay

The «once and for all» SHOW SLAVE STATUS log files & positions explained

MariaDB: AWS RDS read-replica и Seconds_Behind_Master