#AWScommunity #aws #longread #rds #aurora #mysql #airflow #devops #troubleshooting

Часть 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 на инкрементальный там, где можно, и отдельно разобраться, каковаху почему один запрос вообще читает 235 миллионов строк, может там просто индекса не хватает. Завёл тикет команде, которая владеет этим пайплайном, там всё разложено по фактам с командами и логами, а решение, как чинить, оставил за ними, это их трейдофф. Да и я слишком тупой в БД, чтобы умничать и чинить.

#AWScommunity #aws #longread #rds #aurora #mysql #airflow #devops #troubleshooting

Часть 2 из 2.

Внимательный читатель задаст вопрос
"Алекс, кого ты лечишь? РДС не даёт рекомендации, если всего полчаса в день отставание, ты что-то упускаешь, кривой ETL не дал бы такой эффект".
Да, всё так.

Починив ELT/DAG, мы поняли, что рекомендация остаётся даже после этого.
Сняли всю информацию, все метрики клоудвоча, аудит логи - не смогли найти причину. Написали в саппорт. Дали все метрики, в том числе аномальные транзакции.

Буквально в 5-6 итераций общения с саппортом и мы поняли, что все были правы - рекомендация по делу триггерится - по метрике, но сама метрика обманывает.

...
Update: root cause of the TransactionAgeMaximum anomaly is confirmed cosmetic

Our Aurora MySQL engineering team completed an end-to-end root-cause analysis of the ~1.77–1.78 billion-second (~56-year) TransactionAgeMaximum readings — the same class of anomaly you identified. The finding is definitive:

1. The anomaly is caused by a race condition in the engine's transaction start-time path on Graviton (ARM) instance classes, specific to the 3.0x.x engine family. In brief, a transaction's start-time is briefly visible to the metric-gathering poller before it is fully initialized, so the poller computes an age against a near-zero epoch — yielding the nonsensical ~56-year value.

2. Engineering traced the code path end-to-end (from the internal gauge, through information_schema, to CloudWatch) and concluded: "Cosmetic metric anomaly only. No actual long-running transaction, no performance or availability impact." They explicitly found no code path that produces a real transaction behind these readings.
...
Yes — it is safe to proceed the upgrade.

Тот дикий "возраст транзакции в 56 лет" оказался реальным, подтверждённым багом Aurora MySQL 3.*.x на Гравитонах. Race condition в коде движка: поллер метрики иногда читает время старта транзакции чуть раньше, чем оно успело проинициализироваться, и считает возраст от почти нулевой эпохи😬. Никакой реальной транзакции за этим не стоит, чистая косметика в метрике.

А вот прямую связь с тем, что база полгода не возвращается к норме, доказать так и не смогли. Слишком много времени прошло. Так и закрыли: корреляция по времени подтверждена, причинность нет, а вердикт практический: purge здоров, текущий уровень не риск, апгрейду быть.

Апгрейд прошёл отлично.
После апгрейда баг с метрикой ушёл.

Так что же в итоге?
Иногда в процессе подготовки агрейда находишь множество не явных вещей:
- не настроен мониторинг/алёртинг RDS рекомендаций и никто на это не смотрит, а в скоуп уведомлений от Amazon Notification Center это не входит
- схемы/диаграммы надо поддерживать
- нет мониторинга/алёртинга RDS/Airflow на долгие транзакции
- баги. Иногда копаешь неделями, а там ты ваще не виноват, это лишь баги

- - -
* Все умные слова для БД, точные запросы, интерпретация ответов была сделана при помощи значительно более умных коллег, у кого больше опыта с БД.
Сам я как был слабый по БД, так и остался.

** Конечно все знают кто это, аудит показывает, но при блеймлесс калча нельзя кого-либо обвинять. 😬