MariaDB: AWS RDS read-replica и Seconds_Behind_Master

Автор: | 10/07/2018
Нет комментариев

Имеется 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.

Нас интересуют следующие значения:

[simterm]

          Master_Log_File: mysql-bin-changelog.042263
          Read_Master_Log_Pos: 859993

[/simterm]

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

[simterm]

          Relay_Master_Log_File: mysql-bin-changelog.041073
          Exec_Master_Log_Pos: 431032

[/simterm]

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

[simterm]

MariaDB [dbname]> stop slave;
ERROR 1045 (28000): Access denied for user 'root'@'%' (using password: YES)

[/simterm]

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

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

[simterm]

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

[/simterm]

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

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

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

[simterm]

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

[/simterm]

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

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

[simterm]

          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

[/simterm]

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

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

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

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

[simterm]

MariaDB [dbname]> CALL mysql.rds_stop_replication;

[/simterm]

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

[simterm]

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

[/simterm]

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

[simterm]

|     11 | system user |                      | dbname | Slave_SQL |   360504 | Waiting for table metadata lock  | ALTER TABLE android_subscriptions CONVERT TO CHARACTER SET utf8 COLLATE utf8_unicode_ci              |    0.000 |

[/simterm]

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

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

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

[simterm]

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

[/simterm]

Уже 2021 секунд.

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

[simterm]

MariaDB [(none)]> kill 11;
ERROR 1095 (HY000): You are not owner of thread 11

[/simterm]

Ну, ок…

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

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

[simterm]

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 |
+----+-------------+----------------------+-----------+---------+------+--------------------------+------------------+----------+

[/simterm]

И после ребута – “упс”?:

[simterm]

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

[/simterm]

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

Зато – логи, позиции и время отставания от мастера “выровнялись”:

[simterm]

...
        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
...

[/simterm]

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

[simterm]

MariaDB [dbname]> CALL mysql.rds_start_replication;
Query OK, 0 rows affected (0.29 sec)

[/simterm]

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

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

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

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

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

Есть предположение, что на мастере нет бинлога, который пытается читать слейв:
[simterm]
…
Master_Log_File: mysql-bin-changelog.041073
…
[/simterm]
Если так – то можно было бы выполнить mysql.rds_reset_external_master, и обновить имя файла.

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

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

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

[simterm]

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

[/simterm]

Так что почему 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