На днях разбирался с одной относительно простой задачей, но из-за того, что затупил, потратил на неё очень много времени. Так как проделал множество всевозможных операций, решил всё подробно описать. Пригодится в других похожих историях.

Есть MySQL сервер, у которого, как мне показалось, очень большая нагрузка по CPU. Проект немного стух, записи в базу должно быть мало и мне было странно видеть высокую нагрузку от СУБД. Решил разобраться, в чём там дело.

Для начала просто посмотрел нагрузку через top. Mysql почти постоянно кушает одно ядро и периодически остальные дёргает. Дополнительно смотрю в iotop и pidstat и вижу постоянно запись со стороны службы mysqld с pid 19535:

# iotop -obPat
# pidstat -p 19535 -d 1

В таких случаях часто помогает strace. Можно подцепиться к процессу и посмотреть, что он пишет:

# strace -e trace=write -p 19535

В моём случае я не получил результата. В выводе просто было пусто. Я не понял, почему. Стал разбираться дальше. Смотрю потоки процесса:

# ps -L -o spid,%mem,%cpu,cmd 16005

Вижу, что CPU нагружает сильно больше всех остальных один поток с SPID 19547. Смотрю по нему информацию:

# cat /proc/19535/task/19547/stat
# cat /proc/19535/task/19547/status

В выводе только цифры и отсылка к основному потоку mysqld. То есть вообще не понятно, что там реально происходит.

Тут до меня доходит подцепиться к потоку через strace:

# strace -p 19547

Вижу системные вызовы futex (синхронизацией потоков), io_submit (асинхронные операции ввода-вывода) и некоторые другие.

Смотрю, в какие файлы пишет mysqld:

# inotifywait -m /var/lib/mysql

Это ib_logfile0 и xb_doublewrite. Никак не могу понять, почему он туда активно пишет, когда запросов к базе особо нет. И вот тут я как раз и затупил. Я смотрел запросы через mytop и SHOW FULL PROCESSLIST; И там их было очень мало. Эти команды показывают запросы в моменте.

А на серваке выполнялись десятки простых SELECT за считанные миллисекунды или ещё быстрее. Не отслеживал. И они тупо не попадали в вывод. И я думал, что запросов мало, а их было дохрена. Они и давали нагрузку на CPU.

Запросы увидел так. Не перезапуская сервер выполнил в консоли mysql:

> SET GLOBAL general_log = 'ON';
> SET GLOBAL general_log_file = '/var/log/mysql/general.log';

Так же это было видно в выводе:

> SHOW ENGINE INNODB STATUS;

В разделе I/O. Эти потоки отвечают за асинхронные операции ввода-вывода (AIO).

Достаточно было на несколько секунд запустить, чтобы понять всю картину. Потом сразу отключил, чтобы не нагружать диски.

Осталось разобраться, а что на диск то записывается. Вроде как файлы ib_logfile0 это файлы журналов транзакций InnoDB, а разве SELECT вызывает транзакции? Я тут сильно не погружался, но мельком глянул информацию и понял, что всякие очистки устаревших данных, обновление статистики, индексов, хэшей могут тоже провоцировать запись, а точнее обновление этого файла.

xb_doublewrite - это некий буфер InnoDB для повышения надёжности хранения, отключать не рекомендуется, хотя можно.

В общем, время я по сути потратил впустую, если не считать вот эту заметку итоговым результатом. Думаю, она мне ещё понадобится. Времени уже не оставалось дальше разбираться с этой историей. В целом, нагрузка там рабочая, абсолютно некритичная, так что разбираться с ней дальше большой нужды не было. Но я всё равно планирую подумать, как её снизить. И вообще не совсем понятно, почему её так много, с учётом того, что сайт активно кэшируется. Надо будет разбираться.

Отдельно отмечу, что очень активно нагружал этой темой DeepSeek, но он особо не помог. Да, много всякой информации давал и анализировал мои результаты, но фактически я сам догадался в чём причина. Он как-то больше по кругу ходил и всякие команды накидывал.

❗️Если заметка вам полезна, не забудьте 👍 и забрать в закладки.

#mysql #perfomance