MySQL, MVCC, undo logs або Історія одного інциденту
Привіт! Мене звати Павло, я — CTO в Adheart. Наш продукт — інструмент для пошуку та аналізу реклами, який дозволяє за лічені хвилини знаходити найкращі оголошення конкурентів, відстежувати тренди у своїй ніші та запускати більш ефективні рекламні кампанії. Ми збираємо багато реклами з Fb Meta. Дуже багато. Більше 1 млн нових оголошень на день та більше 50 млн оновлень вже існуючих.
Це породжує доволі високий write-load на наші бази даних, зокрема на MySQL (а точніше MariaDB), яку ми використовуємо як основне сховище даних. За весь час роботи в нас накопичився великий досвід в роботі з нею, яким би я хотів поділитись в цій статті, а можливо, і циклі наступних. Залишай свій відгук, якщо даний матеріал був тобі корисним або цікавим 🙂
А почну я з «невеличкого» інциденту в продакшені, який стався зовсім нещодавно. Все почалось з непередбачених та незрозумілих скачків RAM. В нормальних умовах MySQL рідко має виходити за buffer pool size + деякий оверхед на connections, tmp_tables та інший дрібʼязок. В нашому випадку RAM usage роками тримався на позначці ~256G.
На графіку видно, що декілька разів MySQL титанічними зусиллями справилась з оптимізацією памʼяті, аж допоки близько 20:20 не рухнула та не була перезапущена через OOM kill.
Починаємо розбиратись. Стандартно відправляю DevOps проаналізувати метрики, тим часом аналізую наші останні релізи. По метриках — все стабільно (забігаючи наперед: ми збирали не все потрібне, та в постмортемі додали деякі потрібні — про них далі), релізи — дрібні.
Можливі причини виходу MySQL за межі стандартного використання RAM
- Зростання кількості connections (кожне зʼєднання резервує певні буфери під себе).
up to per-thread buffers x N connections, 6M x 1000 = 6Gb - Неоптимізовані запити, що створюють in-memory tmp tables.
up to tmp_table_size x N queries, 4G x 5 = 20G - Збільшені undo logs, які не встигають (або заблоковані) очищуватись.
up to 300B x size, 300B x 100M = 30G - Prepared transactions — транзакції які виконані, але ще не зробили commit.
up to 10MB x Tx, 10MB x 1000 = 10G - ALTER, OPTIMIZE — неочищені кеші. Тут все дуже залежить від розміру таблиць, але з нашою базою в >10Tb може бути безліміт).
Я навів найбільш ймовірні причини зросту використання RAM та орієнтовні цифри, скільки може споживати памʼяті ця причина. В нашому випадку — ми через специфіку навантаження постійно живемо в умовах великих undo logs та prepared transactions (оскільки багато воркерів по збору постійно конкурують за одні й ті самі рядки — попереду рефакторинг, але це інша розмова). Також в цей день ми робили ALTER великої таблиці. Очікувано, саме це і стало причиною інциденту, але дуууже опосередковано. Читай далі.
Пошук проблеми
Отже, починаємо глибше вивчати проблему. Все ускладнюється тим, що база нещодавно пережила рестарт, тому стан аварії частково втрачений. Але вже через 30 хвилин після рестарту:
ps -o pid,vsz,rss,cmd -p $(pidof mariadbd) PID VSZ RSS CMD 3650455 312223904 275984168 /usr/sbin/mariadbd
Маємо 263G — нормальна цифра, але сьогодні вже бачили і більше, тому заспокоюватись поки рано.
SHOW GLOBAL STATUS LIKE 'Max_used_connections'; SHOW GLOBAL STATUS LIKE 'Threads_connected'; Max_used_connections | 1291 Threads_connected | 308
Знову — в межах норми (для наших реалій, ці цифри треба співставляти з тим, що раніше бачили в проді на своїй базі, адже конфіг і профіль навантажень у всіх різний). Але це все після рестарту, і бачимо, що памʼять продовжує підтікати.
mysql -e "show engine innodb status\G" | grep History History list length 601603474
Ооо, а це вже значно цікавіше. 600 млн неочищених undo logs. За формулою вище додаткове споживання RAM може досягати >100G в цьому випадку. Схоже — це наш клієнт, і лишається тільки дізнатись, чому кількість логів стала різко рости. Але спочатку буде непогано нагадати собі про транзаційну модель MySQL.
Транзакції, MVCC та undo logs
InnoDB реалізує транзакції за принципом MVCC (Multi-Version Concurrency Control) — це означає, що кожна транзакція бачить консистентний знімок даних на момент старту, навіть якщо інші транзакції змінюють ті самі рядки. Для цього MySQL створює версії змінених рядків у спеціальному undo log, що зберігається в RAM, допоки ці версії більше не потрібні.
Undo log автоматично очищається процесом purge, але процес може або не справлятись з кількістю логів (інтенсивний write load), або бути заблокований запитами (довготривалі запити вимагають старих рядків, тому процес не може їх очистити). Не треба плутати блокування purge undo logs з дедлоками чи блокуваннями таблиць — це інше. Блокування очистки дозволяє продовжувати зміни в базі, ну, допоки є фізична можливість це робити.
Не буде зайвим по дотичній згадати рівні ізоляції транзакцій, їх всього чотири:
- READ UNCOMMITTED — мінімальний рівень блокувань, дозволяє читати ще незакомічені транзакції та не створює read view (як виявилось пізніше, не у всіх випадках) — відповідно не блокує purge undo logs.
- READ COMMITTED — трохи вище, читаємо вже тільки закомічені транзакції — зберігаємо історію версій. Тут і далі — кожен рівень ізоляції обовʼязково створює read view та блокує очистку undo logs, що й може призвести до різкого зростання History list.
- REPEATABLE READ — режим за замовчанням для InnoDB, створює один read view на всю транзакцію, захищає від dirty і non-repeatable reads.
- SERIALIZABLE — емуляція повного послідовного виконання транзакцій. Максимально суворий режим з усіма наслідками, якщо ви — банкінг, ймовірно вам сюди.
Тобто жоден рівень ізоляції не гарантує відсутність блокувань, а впливає тільки на їх кількість. Це важливо в цьому випадку, адже пізніше ми побачимо, як саме READ UNCOMMITTED створив проблему.
Подальший пошук проблеми та перші помилки
Отже, продовжуємо пошук кореня проблеми. Оскільки розмір undo log відсутній в нашій графані, сколотив за допомогою ChatGPT простий bash one-liner для трекінгу динаміки його розміру.
date && mysql -e "SHOW ENGINE INNODB STATUS\G" | awk '
/History list length/ { print "History list length:", $4 }
/Free buffers/ { print "Free buffers:", $3 }
/Modified db pages/ { print "Dirty pages (Modified db pages):", $4 }'
Очікувано бачу, що з часом History list length ніяк не падає, а тільки росте. Останнім часом ми активно вдосконалюємо нашу систему збору реклами, що призводить до ще більшої кількості записів в таблиці. Приймаємо перше логічне, але помилкове рішення — тимчасово повністю відключити збір, адже побути без нової реклами декілька годин не так страшно, як відключити активним користувачам доступ до сервісу через падіння бази. Рекламу дозбираємо потім, а користувачі активні просто зараз.
Також у гіпотезі, що в нас стало просто більше записів та purge процес не встигає очищати undo logs, максимально тюнимо його та загальний IO-перформанс:
Innodb_io_capacity 200 -> 5000 Innodb_io_capacity_max 2000 -> 20000
Параметри IO capacity в нас були дефолтними та занизькими, для сучасних NVMe-дисків їх можна значно вище підіймати, що ми й зробили. Це мало б допомогти швидше скидати дані на диск — звільняти RAM.
Innodb_purge_batch_size 300 -> 6000 Innodb_max_purge_lag 0 -> 5000000 Innodb_max_purge_lag_delay -> 500
Теоретично маємо швидше очищати undo logs та менше блокувати INSERT/UPDATE (спойлер: практично — ні, адже проблема була не тут).
innodb_purge_threads 6 -> 18 (read only параметр, неможливо змінити без рестарту) — просто збільшити кількість воркерів очистки.
Зробивши всі ці операції (включно зі збільшенням purge threads, рестартом, та переключенням на репліку), як ти здогадуєшся, читачу, ми не отримали рівним рахунком ніякого профіту — History list length продовжував рости, як ніби нічого і не робили. Певно, проблема не в тому, що ми не встигаємо очищати старі записи, а в тому, що їх щось блокує.
Знаходимо справжнього винуватця
Як ми говорили вище, READ UNCOMMITTED в теорії не має спричиняти блокування purge undo logs та є доволі безпечним для системи. Але не завжди. Великі SELECT з GROUP, DISTINCT та інші складні селекти можуть створювати read view та блокувати очистку. Адже, наприклад для GROUP BY системі потрібно бути впевненою, що за час виконання запиту не зʼявляться нові унікальні рядки, по яким виконується групування.
Тому навіть знаючи, що наша аналітична система робить запити з цим рівнем ізоляції, починаємо пошук проблеми в цьому напрямку.
SELECT * FROM information_schema.innodb_trx WHERE trx_is_read_only = 1 AND TIME_TO_SEC(TIMEDIFF(NOW(), trx_started)) > 60; *************************** 1. row *************************** trx_id: 422182318096768 trx_state: RUNNING trx_started: 2025-05-22 22:14:46 trx_requested_lock_id: NULL trx_wait_started: NULL trx_weight: 0 trx_mysql_thread_id: 8610 trx_query: -- Metabase SELECT field AS alias FROM table GROUP BY table.field ORDER BY table.field ASC LIMIT 1000 trx_operation_state: fetching rows trx_tables_in_use: 1 trx_tables_locked: 0 trx_lock_structs: 0 trx_lock_memory_bytes: 1128 trx_rows_locked: 0 trx_rows_modified: 0 trx_concurrency_tickets: 0 trx_isolation_level: READ UNCOMMITTED trx_unique_checks: 1 trx_foreign_key_checks: 1 trx_last_foreign_key_error: NULL trx_is_read_only: 1 trx_autocommit_non_locking: 1
А ось і цінна знахідка: ми використовуємо Metabase в якості системи аналітики, і в нього існує така фонова операція як збір існуючих значень полів в таблицях. Фіча класна, але коли в тебе 2 млрд+ рядків та відсутній індекс — може бути дещо затратною. Власне — наш випадок.
Далі ми витратили ще суттєвий час на те, щоб знайти справжнє джерело запиту, адже виявилось, що це не наш прод метабейз — а його тестовий клон, розгорнутий і забутий багато часу тому. Але це стаття не про наші загальні фейли, а про MySQL, тому не акцентуватиму на цьому увагу. Краще зберемо все воєдино та побудуємо повну ситуацію того, що відбулося.
Чим був винен ALTER
Причиною різкого витоку RAM на MySQL-сервері стало різке зростання undo logs — старих версій оновлених рядків. Через наш високий write load в нас традиційно багато INSERT/UPDATE-операцій, але попри деякі недоліки в конфігурації MySQL ми все одно з ними достатньо коректно справлялись.
Справжньою причиною зросту стали аналітичні запити Metabase, які оновлювали значення полів великої таблиці, і попри найнижчий рівень ізоляції транзакцій все одно створювали блокування очистки, що й призводило до різкого зросту History list length до сотень мільйонів одиниць.
Залишається одне питання — чому це почалось саме в цей день, адже і Metabase, і велика база в нас вже декілька років. І чи винен був ALTER? Ну, винен — наврядче, але причиною став саме він. Ми додали нове поле в таблицю, Metabase побачив це, і вирішив його проіндексувати для зручної роботи з ним надалі. Що призвело до серйозних проблем, які тим не менше ми доволі оперативно вирішили. Весь пошук в нас зайняв біля трьох годин, а сумарний downtime — менше 10 хв (перший раз — коли база впала по OOM killer, другий — переключення на репліку, на жаль, в нас поки без даунтайма не відбувається).
Висновки
Найголовніше — що ми маємо зробити, щоб в майбутньому або унеможливити подібний інцидент, або дізнатись про нього якомога раніше та вчасно відреагувати:
Моніторинг. Моніторингу багато не буває, чим більше метрик своєї системи та інфраструктури ти збираєш — тим краще. Головне — знати, куди дивитись, якщо виникла потреба. І грамотно налаштований алертинг. На жаль, ми використовували доволі простий експортер для MySQL, який давав тільки базові параметри, за якими ми побачили витік RAM, але ніяк не могли знайти його причини. Тому відразу додали три метрики: history list length, free buffers та trx duration — для виявлення проблем з очисткою undo logs та довгими транзакціями.
Регулярний аналіз моніторингу. Це окремий пункт, в моніторинг ми зазвичай дивимось тільки коли щось пішло не так. Плануємо ввести щомісячний звіт по стану критичних компонентів, в якому будемо аналізувати наші метрики, їх зміни за останній час. Шукати, що не так, навіщо якщо візуально вони виглядають добре.
Перегляд конфігурацій. Останній раз ми змінювали конфіг бази, мабуть, рік тому. І даремно, оскільки продукт росте, а команда здобуває нові знання — тому перегляд і оптимізація конфігів має стати регулярною процедурою також.
Аудит доступу до критичних систем. Дуже весело шукати запит, який йде невідомо від кого і звідки, але тільки якщо це розвага вихідного дня, а не ніч в прод-середовищі.
Оптимізація кодової бази та навантажень. Рано чи пізно техборг доводиться ліквідовувати. І той процес, який ми створили, хоч і дозволяє повною мірою виконувати поставлені продуктові задачі та збирати мільйони реклами, але створює високе навантаження, з яким навіть потужна інфраструктура не завжди може справитись. Сподіваюсь, вже скоро я зможу розповісти й про це — буде цікаво!
Це історія лише одного інциденту, і я сподіваюсь, що наш досвід допоможе тобі або уникнути такої ситуації, або швидше зрозуміти причини та відреагувати на нього. Якщо цей матеріал був для тебе цікавий — буду радий коментарю, підказці чи поправці. Нам є ще багато чим поділитись, тому, сподіваюсь — до зустрічі!
SuperDev
Eugen Stogniy
Владислав Соколенко
Ivan Pyrog
Владислав Соколенко
Pavel Katiushyn
12 коментарів
Додати коментар Підписатись на коментаріВідписатись від коментарів