Часть 1 из 2.
Короче, понадобилось нам обновлять Aurora MySQL с одной мажорной версии на другую.
Дело обычное, но перед любым мажорным апгрейдом продовой базы я по гайду иду смотреть, что у нас там висит в RDS Recommendations. И тут внезапно выясняется: на этом проекте мы туда вообще не смотрели. Ни разу. Никто и никогда. Стоит себе панель рекомендаций в консоли, что-то там подсвечено жёлтым и красным, и всем как-то норм.
Полез разбираться.
Первым делом сделал то, что должен был сделать ещё полгода назад: завёл алерт.
На память связка EventBridge + SNS + питон лямбда + слак вебхук.
Раз в неделю по понедельникам в Slack прилетает дайджест активных рекомендаций по нашим RDS.
Не срочный инцидент, просто напоминалка, чтобы это больше никогда тихо не копилось год.
И буквально в первом же прогоне вижу:
"The InnoDB history list length increased significantly".
Активна с августа. Полгода висела.
Смотрю, что это вообще такое. History list length это, как я понимаю, количество ещё не почищенных undo-записей в InnoDB.
Растёт когда purge не успевает убирать за транзакциями. Амазон в описании рекомендации прямо пишет: чинить это нужно ДО мажорного апгрейда, потому что при апгрейде движок долго разбирает этот список, и чем он больше, тем дольше и опаснее апгрейд.
Всё, приехали, это блокер апгрейда. 😢
Ладно, начали копать.
Первая гипотеза была самая очевидная и, как оказалось, неверная.
У нас есть ETL-пайплайн на сраном Эйрфлоу, который раз в сутки синкает MySQL в Snowflake. Смотрю на архитектурную схему пайплайна в не менее сраном Confluence, вижу коробочку "Aurora MySQL prod", стрелочка от Airflow прямо в неё. Ну всё, думаю, вот он, виновник, тащит данные прямо с мастера, долгая транзакция на райтере, отсюда и history list.
Написал коллегам из дата-команды: "у нас, похоже, Airflow бьёт напрямую в master, из-за этого и растёт список".
Ответ был короткий и справедливый: "у нас Database Insights показывает Airflow на ридере, как обычно. Дайте данные, а не предположение".
Справедливо. Полез проверять руками, а не по картинке из confluence.
Достал security groups у MWAA-окружения, нашёл ENI airflow-воркера, сравнил security groups с тем, что у MWAA в конфиге. Совпало. Дальше через Performance Insights посмотрел топ хостов по нагрузке на ридере и на райтере за то же окно времени. IP воркера Airflow, топ-1 по нагрузке на ридере. На райтере в топ-25 вообще не встречается.
Гипотеза номер один, красиво описанная на диаграмме, была мимо.
Дело было не в мастере.
Ладно, обделался я со своей гипотезой, ну да ладно, бывает.🤡
Думаю, может тогда это просто какая-то одна зависшая транзакция сидит прямо на райтере, не важно кто её открыл. Полез сам* в
information_schema.innodb_trx. Смотрю на текущий момент: пусто, всё свежее, самой старой транзакции пара секунд. Может, просто не попал в момент.
Написал кронджобу в кластере, которая раз в две минуты в течение трёх часов дампила
innodb_trx и заодно information_schema.replica_host_status (там лаг репликации и LSN между узлами кластера). Три часа честного сбора данных на самом продовом окне, когда метрика скачет. Результат: максимальный возраст любой транзакции на райтере за все 90 замеров - три секунды. Лаг у ридера тоже никакой, пара миллисекунд.
Второй заход, снова в пустоту. На этом моменте я, если честно, уже начал придумывать какую-то дичь про баг в самой Aurora. Типа напилить тикет в саппорт.
Тут вспомнил про slow query log.
У нас он давно экспортится в CloudWatch Logs, просто никто туда не смотрел в контексте этой задачи. Полез в лог именно ридера, за тот же временной диапазон, что и в первой гипотезе.
И вот тут наконец что-то нашлось:
# User@Host: airflow[airflow] @ [10.0.x.x]
# Query_time: 1738.868051 Lock_time: 0.000002 Rows_sent: 6232112 Rows_examined: 19477050
Запрос от airflow, 1738 секунд, это почти 29 минут. Причём это не единичный случай, за одно окно таких штук пять, самая длинная под полчаса, самая прожорливая разбирает 235 миллионов строк за один присест (!!!). И всё это на ридере, не на райтере!!!.
То есть гипотеза номер один была не совсем мимо, просто немного не в ту сторону: эйрфлоу правда виноват, просто сидит не там, где я думал.
Дальше уже дособрал картину той же кронджобой, которую сделал для проверки транзакций. Стал смотреть не только на
innodb_trx, а на oldest_read_view_trx_id у ридера. И увидел: этот trx_id замер на 15 замеров подряд, это примерно 28 минут, пока LSN* у ридера спокойно рос дальше. То есть репликация не отставала, но снепшот данных для конкретного долгого запроса не двигался почти полчаса.Полез читать документацию Амазона по этой самой рекомендации (ссылка ниже, она буквально прямо в описании рекомендации в консоли лежит, просто никто не читал):
- https://docs.aws.amazon.com/AmazonRDS/latest/AuroraUserGuide/proactive-insights.history-list.html
- https://aws.amazon.com/blogs/database/achieve-a-high-speed-innodb-purge-on-amazon-rds-for-mysql-and-amazon-aurora-mysql/
Цитата оттуда: если у вас райт-интенсивная нагрузка на праймари и одновременно долгие запросы на репликах, вы получите backlog по purge, потому что гарбадж коллектор блокируется этими долгими запросами.
У Aurora storage общий на весь кластер. Покурить на ридере полчаса можно, но платит за это весь кластер, включая райтер, потому что purge физически не может продвинуться дальше самого старого read view во всей этой семье инстансов. Не важно, читает мастер или реплика, движок про это ничего не знает, ему важен только самый старый снепшот.
Вот и весь секрет полугодовой рекомендации: раз в сутки прилетает ETL-синк, читает половину базы одним долгим SELECT-ом на ридере, и весь кластер полчаса не может почистить за собой.
Отдельно нашёл забавную деталь.
Кто-то** из коллег ещё в начале месяца руками (не через терраформ, просто в консоли😁) поднял
max_execution_time на параметр-группе ридера до 30 минут. Видимо, до этого запрос просто убивался по таймауту и синк не долетал. То есть кто-то уже наступил на эти грабли раньше меня, просто не докопался до причины, а тупо дал запросу больше времени. Запрос стал долетать, но теперь честно душит purge все эти полчаса.Фикс, если коротко: чинить надо не базу, а сам DAG в этом случае.
Резать один гигантский full-table sync на куски поменьше, переводить больше таблиц с полного sync на инкрементальный там, где можно, и отдельно разобраться,