Профилирование запросов в Mysql применяется для оценки производительности вашего приложения. При разработке средних и больших приложений приходится иметь дело с сотнями запросов распределенными по вашему коду, которые исполняются каждую секунду. Без техники профилирования запросов бывает очень сложно найти из-за чего страдает быстродействие вашего приложения.
Что такое лог медленных запросов в MySQL?
Лог медленных запросов в MySQL — лог, отмечающий медленные и потенциально проблемные запросы. MySQL по умолчанию поддерживает такой функционал, но он отключен. При помощи настройки определенных переменных сервера мы можем указать какие именно запросы нас интересуют. Чаще всего нам нужны запросы которые требуют определенное количество времени на своё выполнение или запросы, которые некорректно обрабатывают индексы.
Настройка переменных профилирования
Основные переменные для настройки лога запросов:
slow_query_log G
slow_query_log_file G
long_query_time G / S
log_queries_not_using_indexes G
min_examined_row_limit G / SЗамечание: G — глобальные переменные, S — системные переменные
- slow_query_log — булево значение включающее лог
- slow_query_log_file — абсолютный путь к файлу лога. Владельцем каталога должен быть пользователь mysqld, а также директория должна иметь корректные разрешения для чтения и записи. Чаще всего демон mysql работает от имени пользователя mysql.
Для проверки выполните следующую команды:
ps -ef | grep bin/mysqld | cut -d' ' -f1Вывод команды даст вам имя текущего пользователя и пользователя mysqld. Пример настройки директории /var/log/mysql:
cd /var/log
sudo mkdir mysql
sudo chmod 755 mysql
sudo chown mysql:mysql mysql- long_query_time — время в секундах для проверки продолжительности запроса. Например, при значении 5, каждый запрос продолжительностью более 5 секунд будет записан в лог.
- log_queries_not_using_indexes — булево значение, включает сохранение запросов не использующих индексы. Такие запросы очень важны при анализе.
- min_examined_row_limit — указывает минимальное значение количества рядов данных для анализа. Значение 1000 проигнорирует запросы возвращающие меньше 1000 рядов значений.
Установить эти переменные можно в конфигурационном файле MySQL, динамически через MySQL GUI или командную строку MySQL. Если переменные указаны в конфигурационном файле, то сервер установит их при очередном запуске. Обычно этот файл располагается по адресу /etc, /usr, /etc/my.cnf или /etc/mysql/my.cnf. Вот команды поиска файла конфигурации (иногда следует расширить поиск на другие корневые каталоги):
find /etc -name my.cnf
find /usr -name my.cnfКогда найдете файл, добавьте требуемые переменные в разделе [mysqld]:
[mysqld]
; …
slow-query-log = 1
slow-query-log-file = /var/log/mysql/localhost-slow.log
long_query_time = 1
log-queries-not-using-indexes ; тут не надо значениеИзменения вступят только при очередном запуске MySQL, если вам необходимо динамическое изменение параметров, используйте другие методы установки переменных:
mysql> SET GLOBAL slow_query_log = 'ON';
mysql> SET GLOBAL slow_query_log_file = '/var/log/mysql/localhost-slow.log';
mysql> SET GLOBAL log_queries_not_using_indexes = 'ON';
mysql> SET SESSION long_query_time = 1;
mysql> SET SESSION min_examined_row_limit = 100;Проверить значения переменных можно следующим образом:
mysql> SHOW GLOBAL VARIABLES LIKE 'slow_query_log';
mysql> SHOW SESSION VARIABLES LIKE 'long_query_time';Основной недостаток динамической установки — значения будут потеряны при запуске системы. Рекомендуется указывать важные параметры в конфиге MySQL.
Заметка: Синтаксис динамической установки параметров через команду SET и с использованием конфигурационного файла немного различается, например
slow_query_log/slow-query-log. В официальной документации СУБД вы найдете полное описание синтаксиса. ФорматOption-Fileиспользуется для файла конфигурации,System Variable Name— имена переменных при динамической установке значений.
Генерация данных для профилирования запроса
Мы рассмотрели основные пункты настройки профилирования, теперь создадим интересующие нас запросы. Этот пример использовался на запущенном MySQL сервере без каких либо предварительных настроек лога. Примеры запросов можно запускать как через MySQL GUI, так и командными средствами СУБД. При мониторинге лога медленных запросов, часто открывают два окна с соединением: одно для запуска запросов, другое — для просмотра лога.
Откройте консоль MySQL и авторизуйтесь от имени SUPER ADMIN. Для начала создайте тестовую БД и таблицу, внесите некоторые данные в неё и включите профилирование. Этот пример следует запускать в окружении разработки:
$> mysql -u -pmysql> CREATE DATABASE profile_sampling;
mysql> USE profile_sampling;
mysql> CREATE TABLE users ( id TINYINT PRIMARY KEY AUTO_INCREMENT, name VARCHAR(255) );
mysql> INSERT INTO users (name) VALUES ('Walter'),('Skyler'),('Jesse'),('Hank'),('Walter Jr.'),('Marie'),('Saul'),('Gustavo'),('Hector'),('Mike');
mysql> SET GLOBAL slow_query_log = 1;
mysql> SET GLOBAL slow_query_log_file = '/var/log/mysql/localhost-slow.log';
mysql> SET GLOBAL log_queries_not_using_indexes = 1;
mysql> SET long_query_time = 10;
mysql> SET min_examined_row_limit = 0;Теперь у нас есть БД с тестовыми данными. Мы запустили профилирование, но время срабатывания и количество строк мы специально установили малым. Чтобы просмотреть лог воспользуйтесь командой:
cd /var/log/mysql
ls -lПо идеи, файла лога ещё не должно существовать, так как мы не сделали запросов к БД. Если же он существует, то это означает что профилирование было настроено ранее, а это может исказить результаты примера. Выполните в консоли :
mysql> USE profile_sampling;
mysql> SELECT * FROM users WHERE id = 1;Наш запрос использует Primary Key индекс из таблицы. Запрос отработал очень быстро с использованием индекса, поэтому в логе он не должен отразиться. Обратите внимание, файл лога не должен был создаться.
Теперь выполните следующее:
mysql> SELECT * FROM users WHERE name = 'Jesse';Здесь мы не использовали индексов. Теперь мы должны увидеть этот запрос в логе:
sudo cat /var/log/mysql/localhost-slow.log
# Time: 140322 13:54:58
# User@Host: root[root] @ localhost []
# Query_time: 0.000303 Lock_time: 0.000090 Rows_sent: 1 Rows_examined: 10
use profile_sampling;
SET timestamp=1395521698;
SELECT * FROM users WHERE name = 'Jesse';Рассмотрим ещё один пример. Поднимите планку количества строк в ответе и выполните следующий запрос:
mysql> SET min_examined_row_limit = 100;
mysql> SELECT * FROM users WHERE name = 'Walter';Запрос не отразится в логе, так как мы не превысили 100 строк в ответе на запрос.
Заметка: Если данные не отображаются в логе, то в первую очередь нужно рассмотреть следующие факторы. Первое — права на каталог, где хранится файл лога. Группа и пользователь должны соответствовать пользователю mysqld, права должны быть — chmod 755. Второе — возможно профилирование было настроено ранее. Удалите все существующие значения переменных профилирования из файла конфигурации и перезапустите сервер или установите переменные динамически. Если вы использовали динамический метод, то выйдете и зайдите снова в консоль MySQL.
Анализ данных профилирования запросов
Рассмотрим вышеприведенный пример:
# Time: 140322 13:54:58
# User@Host: root[root] @ localhost []
# Query_time: 0.000303 Lock_time: 0.000090 Rows_sent: 1 Rows_examined: 10
use profile_sampling;
SET timestamp=1395521698;
SELECT * FROM users WHERE name = 'Jesse';Здесь мы видим:
- Время, когда был запущен запрос
- Пользователь, который выполнил запрос
- Время работы запросы
- Продолжительность блокировки
- Количество выбранных строк
- Количество проанализированных строк
Эти данные очень полезны, так как при их помощи мы сможем найти и устранить причину замедления системы. Так же разработчик или администратор MySQL всегда сможет увидеть проблемные запросы и хочется отметить, что тут их найти гораздо быстрее, чем изучая программный код приложения. При длительном профилировании можно отследить условия работы при низком быстродействии.
Использование mysqldumpslow
Лог постоянно записывает данные, как правило, пишет он намного больше, чем из него читают. При большом размере лога, читать его становится проблематично. В состав MySQL входит инструмент mysqldumpslow, который помогает сохранить целостность лога. Сама программа совмещена с MySQL (на Linux системах). Для её использования выполните необходимую команду и передайте ей путь до лог файла:
sudo mysqldumpslow -t 5 -s at /var/log/mysql/localhost-slow.logСуществует ряд параметров помогающих настроить вывод команды. В примере ниже мы увидим пять последних запросов отсортированных по средней продолжительности. В результате читать лог становится намного удобнее. (вывод изменен, чтобы показать реальные значения в логе):
Count: 2 Time=68.34s (136s) Lock=0.00s (0s) Rows=39892974.5 (79785949), root[root]@localhost
SELECT PL.pl_title, P.page_title
FROM page P
INNER JOIN pagelinks PL
ON PL.pl_namespace = P.page_namespace
WHERE P.page_namespace = N
…Что мы видим:
- Count — количество вхождений запроса в лог
- Time — среднее и общее время запроса
- Lock — время блокировки таблицы
- Rows — Количество выбранных строк
Команда исключает числовые и строковые данные запроса, то есть запросы с одинаковым условием WHERE будут считаться одинаковыми. Благодаря такому инструменту не приходится постоянно просматривать лог. За счет большого количества параметров команды, можно отсортировать вывод как вам удобно. Так же существуют разработки сторонних разработчиков с похожим функционалом, например pt-query-digest.
Разбивка запросов
Следует уделить внимание ещё одному инструменту, который позволяет разбивать сложные запросы. Чаще всего приходится брать запрос из лога, а потом запускать его прямо в консоли MySQL. Сначала надо включить профилирование, а затем выполнить запрос:
mysql> SET SESSION profiling = 1;
mysql> USE profile_sampling;
mysql> SELECT * FROM users WHERE name = 'Jesse';
mysql> SHOW PROFILES;После включения профилирования, SHOW PROFILES покажет таблицу связывающую Query_ID и SQL выражение. Найдите соответствующий Query_ID и выполните следующий запрос (замените # на ваш Query_ID):
mysql> SELECT * FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID=#;Пример вывода:
SEQ STATE DURATION
1 starting 0.000046
2 checking permissions 0.000005
3 opening tables 0.000036STATE — шаг в процессе выполнения запроса, DURATION — продолжительность шага в секундах. Этот инструмент не так уж часто используется, но иногда он может быть чрезвычайно полезен в определении причины снижении скорости запроса.
Детальное описание столбцов:
http://dev.mysql.com/doc/refman/5.5/en/profiling-table.html
Детальное описание шагов:
http://dev.mysql.com/doc/refman/5.5/en/general-thread-states.html
Заметка: этот инструмент не следует использовать в рабочем режиме сервера, за исключением анализа специфических запросов.
Быстродействие лога медленных запросов
Последний вопрос — как сказывается работа профилирования на быстродействие сервера в целом. В продуктовом режиме сервера можно вполне спокойно использовать такое логирование, оно не должно сказываться ни на CPU ни на I/O. Тем не менее стоит обратить внимание на размер файла лога, он не должен становится непомерно большим. Так же из опыта хотелось бы отметить, что устанавливать значение переменной long_query_time стоит равным от 1 секунды и выше.
Важно: не стоит использовать инструмент профилирования —
SET profiling = 1— для записи всех запросов, т.е. переменную general_log в продуктовом режиме и при больших нагрузках не рекомендуется использовать.
Заключение
Профилирование запросов может вам очень помочь в выделении проблемного запроса и в оценке общей производительности. Также разработчик может изучить как работают запросы MySQL его приложения. Инструмент mysqldumpslow помогает просматривать и обрабатывать лог запросов. После определения проблемных запросов останется настроить их на максимальную производительность.