Настраиваем лог медленных запросов MySQL

Нас будут интересовать 5 глобальных переменных в MySQL

1. long_query_time — float значение медленных запросов в секундах
2. slow_query_log — флаг включения/отключения лога ON/OFF
3. slow_query_log_file — путь для сохранения лога медленных запросов
4. log_queries_not_using_indexes — флаг включения/отключения логгирования запросов не юзающих индексы
5. min_examined_row_limit — минимальное количество обработанных запросом строк, для попадания его в лог

Метод 1. Логгируем до первого ребута.

На этом примере разберем переменные и их значения, поэтому, если нужно реально жестко настроить сервер на логгирование медленных запросов, чтобы это работало и после перезагрузки, то лучше сразу перейти к методу 2. Заходим под root в терминале в mysql и проверяем наши настройки ведения логов медленных запросов:

show variables where variable_name like '%slow_query_log%' or variable_name like '%long_query_time%';

Включаем лог запросов, устанавливаем переменную в 1 секунду, устанавливаем файл лога и включаем настройки в текущей сессии. После чего проверяем настройки:

set global slow_query_log='ON';
set global long_query_time = 1;
set global slow_query_log_file = '/var/log/mysql/mysql_slow.log';
set @@SESSION.slow_query_log = 'ON';
set @@SESSION.long_query_time = 1;
show variables where variable_name like '%slow_query_log%' or variable_name like '%long_query_time%';

Выполним от пары разных пользователей пару медленных запросов по 5 сек. DO sleep(5); и посмотрим в наш лог медленных запросов mysql:

cat /var/log/mysql/mysql_slow.log

Отлично, это полная инфа по медленным запросам, но неплохо было бы их выбрать голенькими, чисто одни запросы, без лишней шелухи. В этом как всегда поможет товарищ grep:

cat /var/log/mysql/mysql_slow.log | grep "SET timestamp" -A1 | grep -v "SET timestamp"

Или awk, что выглядит элегантнее:

awk '/SET timestamp/{getline; print}' /var/log/mysql/mysql_slow.log

Ну а sed ещё короче:

sed -n '/SET timestamp/{n;p;}' /var/log/mysql/mysql_slow.log

sed the winner!

Когда надо выделить запросы из только определенной базы:

cat mysql-slow.log | sed '/timestamp/d' | grep "use db_name;" -A2 -B2 > slow.log

А теперь ребутнем сервер или рестартанем mysql и проверим настройки:

show variables where variable_name like '%slow_query_log%' or variable_name like '%long_query_time%';

Печалька. Всё потеряно. Логгирование медленных запросов отключено.

Метод 2. Настройка my.cnf

Установим логгирование медленных запросов mysql на уровне системы, чтобы не потерять настройки после перезагрузки сервера:

nano /etc/mysql/my.cnf

Или любой другой текстовый редактор. И в файле поправим/добавим значения переменных:

long_query_time = 1
slow_query_log = ON
slow_query_log_file = /var/log/mysql/mysql_slow.log
log_queries_not_using_indexes = ON
min_examined_row_limit = 1000

log-queries-not-using-indexes, если желаем получать не только медленные запросы, но и запросы не использующие индексы. В лог будут попадать все запросы не использующие индексы, что существенно осложнит чтение журнала и забъет его под завязку, если не установить дополнительно min_examined_row_limit! Эта переменная говорит серверу, какое количество строк должно быть обработано запросом, чтобы он попал в наш лог. Потому что, нет ничего страшного для производительности, если в таблицах с маленьким количеством записей не используются индексы(некоторые считают малым до 10000 записей). И если мы не зададим данный параметр переменной min_examined_row_limit и тем самым оставим лимит по умолчанию равным 0, то лог медленных запросов порядком засрется вполне себе нормальными, быстрыми запросами. Но, в тоже время, если мы его зададим, то запросом DO SLEEP(5);  уже проверить логгирование не сможем. Перезапускаем mysql сервер:

service mysql restart
# или
systemctl restart mariadb

Проверяем настройки из консоли mysql или из phpmyadmin:

show variables where variable_name like '%slow_query_log%' or variable_name like '%long_query_time%' or variable_name like '%not_using_indexes%' or variable_name like '%min_examined%';

Или прямо из терминала под root:

mysql -e "show variables where variable_name like '%slow_query_log%' or variable_name like '%long_query_time%' or variable_name like '%not_using_indexes%' or variable_name like '%min_examined%';"

После рестарта mysql или рестарта всей системы настройки переменных для ведения журнала mysql_slow.log должны выглядеть так, как показано выше. Теперь всё железно — restart, reboot и shutdown логгирование медленных запросов не отключат. Но добавив log-queries-not-using-indexes мы набили лог не только медленными запросами, но и не использующими индексы. Оставим grep сотоварищи в покое и отсортируем slow лог журнал mysql специально созданной для него утилитой mysqldumpslow

mysqldumpslow -t 10 -s at /var/log/mysql/mysql_slow.log

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

• -t n говорит сколько топовых запросов показать
• -s at сортировка топа по среднему времени выполнения
• -s c сортировка по количеству запросов

Сортировка также возможна по максимальному времени выполнения -s t и ряду многих других параметров, включая даже паттерны регулярок. Вот например проанализируем топ 10 запросов по общему количеству для определенной базы

mysqldumpslow -t 10 -g "use db_name;" -s c /var/log/mysql/mysql_slow.log

Сохраняем лог файл mysql_slow.log в копию и начинаем его запись с нуля

mv /var/log/mysql/mysql_slow.log /var/log/mysql/mysql_slow.old
mysql -e "FLUSH SLOW LOGS;"
# или так, если старый файл лога не нужен
rm /var/log/mysql/mysql_slow.log
mysql -e "FLUSH SLOW LOGS;"

В следующих записках о MySQL разберем индексы и настройки кеша запросов в бд.

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

cat mysql-slow.log | grep -E "^use" | sort | uniq
# выводим список всех юзаемых баз
cat mysql-slow.log | sed -e '/timestamp/d' -e 's/\\"//g' -e 's/"[^"]*"/"S"/g' | grep "use db_name;" -A1 | sed -r 's/ [0-9]+/ N/g' | sort | uniq
# вывести списоком уникальные шаблоны запросов для указанной базы

# а вот так ваще мощно
 cat mysql-slow.log | sed -e '/timestamp/d' -e 's/\\"//g' -e 's/"[^"]*"/"S"/g' | grep "use db_name;" -A1 | sed -r 's/ [0-9]+/ N/g' | sed '/^--$/d' | sort | uniq -c | sort -rn
# выводим списком уникальные шаблоны запросов для указанной базы с их сортировкой и количеством

А эту прелесть, подсказала моя лень. Передаешь ей в параметре имя файла mysql-slow.log и на выходе получаешь результат разделенный по всем базам и отсортированный по количеству запросов.

#!/bin/bash
file=$1
echo -e "\nSlow query analysis program launched ...\n"
cat $file | grep '^# Time:' | sed -e 1b -e '$!d' | sed ':a; /$/N; s/\n//; ta' | sed 's/# Time:/ -/2' | sed 's/Time/Log time range/'
echo ------------------------------------------------
cat $file | grep -E "^use" | sort | uniq | while read line
do cat "$file" | sed -e '/timestamp/d' -e 's/\\"//g' -e "s/\\'//g" -e 's/"[^"]*"/"S"/g' -e "s/'[^']*'/"S"/g" | grep "$line" -A1
echo ------------------------------------------------
done
exit

Используем так:

chmod +x anlzslow.sh
# не забудьте права на исполнение дать сперва и юзаем
./anlzslow.sh mysql-slow.log