Дополнительная статистика о медленных запросах: log_slow_extra
Дата: 4.03.2019
Перевод статьи Jesper Krogh. Оригинал - More statistics for slow queries: log_slow_extra
Лог медленных запросов - старый надежный способ фиксации медленных запросов, который позволяет администратору определить какие запросы в первую очередь нуждаются в оптимизации. Начиная с MySQL 5.6 появилась возможность использовать для этой цели Performance Schema, которая имеет более низкие накладные расходы. Однако, лог медленных запросов имеет одно важное преимущество - данные не исчезают (т.к. записываются на диск в отличии от таблиц Performance Schema, которые хранятся в памяти и не используют постоянное дисковое хранилище). В недавно вышедшей MySQL 8.0.14 лог медленных запросов стал более удобным инструментом за счет добавления дополнительных параметров выполнения запроса.
Спасибо Facebook за патч, на котором основано это улучшение.
По умолчанию дополнительная информация не записывается в лог, чтобы включить эту опцию используйте переменную log_slow_extra:
mysql> SET PERSIST log_slow_extra = ON;
Query OK, 0 rows affected (0.05 sec)
SET PERSIST используется для того, чтобы изменения конфигурации сохранились при перезагрузке сервера MySQL. Если вы хотите сначала попробовать новую возможность (а потом уже решать оставить ли её включенной по умолчанию), используйте SET GLOBAL.
Это всё что требуется для настройки. Теперь можно выполнить "медленный" запрос и посмотреть данные, записанные в лог. Простейший способ получить медленный запрос - выполнить DO SLEEP(...), где вместо троеточия указать количество секунд, на которое будет произведена задержка. Однако, это не очень интересный для анализа запрос. Другой путь - уменьшить long_query_time настолько, чтобы запрос попал в лог. Если установить значение long_query_time равным нулю, в лог будут записываться все запросы:
mysql> SET SESSION long_query_time = 0.0;
Query OK, 0 rows affected (0.01 sec)
Обратите внимание:
Включение лога медленных запросов несет дополнительные накладные расходы. Не рекомендуется использовать его непрерывно с long_query_time = 0 для всех подключений. Это может привести к проблемам с производительностью.
Поэтому в примере выше указан SET SESSION, чтобы изменение long_query_time повлияло только на текущую сессию.
Давайте выполним следующий запрос:
mysql> SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
+------+------------------+-------------+------------------+------------+
| ID | Name | CountryCode | District | Population |
+------+------------------+-------------+------------------+------------+
| 1024 | Mumbai (Bombay) | IND | Maharashtra | 10500000 |
| 2331 | Seoul | KOR | Seoul | 9981619 |
| 206 | São Paulo | BRA | São Paulo | 9968485 |
| 1890 | Shanghai | CHN | Shanghai | 9696300 |
| 939 | Jakarta | IDN | Jakarta Raya | 9604900 |
| 2822 | Karachi | PAK | Sindh | 9269265 |
| 3357 | Istanbul | TUR | Istanbul | 8787958 |
| 2515 | Ciudad de México | MEX | Distrito Federal | 8591309 |
| 3580 | Moscow | RUS | Moscow (City) | 8389200 |
| 3793 | New York | USA | New York | 8008278 |
+------+------------------+-------------+------------------+------------+
10 rows in set (0.04 sec)
Это приведет к появлению в логе медленных запросов записи вида:
# Time: 2019-01-31T07:24:20.518505Z
# User@Host: root[root] @ localhost [::1] Id: 15
# Query_time: 0.001827 Lock_time: 0.000087 Rows_sent: 10 Rows_examined: 4089 Thread_id: 15 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 694 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 4080 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 10 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2019-01-31T07:24:20.516678Z End: 2019-01-31T07:24:20.518505Z
SET timestamp=1548919460;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
Для сравнения, запись о том же самом запросе при log_slow_extra = OFF будет иметь вид:
# Time: 2019-01-31T07:24:06.100447Z
# User@Host: root[root] @ localhost [::1] Id: 15
# Query_time: 0.002286 Lock_time: 0.000133 Rows_sent: 10 Rows_examined: 4089
SET timestamp=1548919446;
SELECT * FROM world.city ORDER BY Population DESC LIMIT 10;
Продублируем дополнительные параметры в более удобном для восприятия виде:
- Thread_id: 15
- Errno: 0
- Killed: 0
- Bytes_received: 0
- Bytes_sent: 694
- Read_first: 1
- Read_last: 0
- Read_key: 1
- Read_next: 0
- Read_prev: 0
- Read_rnd: 0
- Read_rnd_next: 4080
- Sort_merge_passes: 0
- Sort_range_count: 0
- Sort_rows: 10
- Sort_scan_count: 1
- Created_tmp_disk_tables: 0
- Created_tmp_tables: 0
- Start: 2019-01-31T07:24:20.516678Z
- End: 2019-01-31T07:24:20.518505Z
P.S. несколько слов от переводчика:
Дополнительная статистика записывается только в файл журнала медленных запросов (т.е. log_output равен или содержит значение FILE). При записи лога в системную таблицу эффекта от включения log_slow_extra не будет.
В MySQL 5.7 был изменен формат отображения временных меток в лог файлах. Теперь в качестве разделителя между датой и временем используется символ "Т", а "Z" в конце указывает на использование временной зоны по умолчанию - UTC. Подробнее можно прочитать в другой статье автора - The Format for Timestamps in MySQL Logs
До MySQL 8.0.14 в строке SET timestamp указывалось время, когда запрос был записан в лог, что происходило после того, как запрос завершал работу. Теперь отображается время, когда запрос начал выполняться.
Дата публикации: 4.03.2019
© Все права на данную статью принадлежат порталу SQLInfo.ru. Перепечатка в интернет-изданиях разрешается только с указанием автора и прямой ссылки на оригинальную статью. Перепечатка в бумажных изданиях допускается только с разрешения редакции.
|
