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

Иногда нам нужно, определить почему SQL обрабатывается медленно. Конечно, это может зависеть от конфигурации, от железа, от неправильной схемы и от неправильного SQL запроса. Один из инструментов определения это лог медленных запросов.

Чтобы включить лог медленных запросов, нужно открыть конфигурационный файл MySQL (путь может отличаться):

sudo gedit /etc/mysql/my.cnf

и изменить настройки:

log_slow_queries = /var/log/mysql/mysql-slow.log
long_query_time = 1

log_slow_queries - указывает путь к файлу настроек long_query_time - указывает минимальное время выполнения запроса, после которого он считается медленным в секундах,

После этого необходимо перезапустить MySQL:

/etc/init.d/mysql restart

После этого в файл /var/log/mysql/mysql-slow.log будут попадать медленные запросы которые больше заданого времени в конфиге

mysqldumpslow

Для обработки и анализа лога медленных запросов предназначена консольная команда mysqldumpslow с таким синтаксисом: mysqldumpslow [options] [log_file ...].

mysqldumpslow группирует похожие запросы, заменяя числа и строки в запросах на N и 'S'. Наиболее полезные опции это:

• -s sort_type — тип сортировки запроса, обычно используются типы:
  • t — по времени запроса,
  • at — по среднему времени запроса,
  • c — по количеству запросов;
• -t N — показывает только N запросов при выводе;
• -g pattern — фильтрует запросы по шаблону pattern (в стиле команды grep).

По умолчанию используется сортировка по среднему времени запроса -s at.

Пример, чтобы получить 10 самых частых медленных запросов в файл top10-by-count.log:

mysqldumpslow -s c -t 10 /var/log/mysql/mysql-slow.log > top10-by-count.log

Percona Toolkit

Еще есть отличный инструмент Percona Toolkit

Для установки нужно использовать

apt-get install percona-toolkit

Запуск анализа по логу

pt-query-digest /var/log/mysql/mysql-query.log > digest.txt

После этого будет сгенерирован достаточно длинный отчет. Сверху будет приведена общая информация о всех медленных запросах:

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           634s      1s     54s      4s      8s      6s      2s
# Lock time            7ms       0   953us    48us   167us   151us       0
# Rows sent        107.62M       0   1.52M 720.30k   1.46M 619.39k 462.39k
# Rows examine     107.62M       0   1.52M 720.30k   1.46M 619.38k 462.39k
# Query size        70.38k      45  10.94k  471.04   88.31   1.93k   49.17

Обратите внимание на медианы. В примере — половина всех запросов выполняется дольше 2 секунд — это плохо.

Ниже можно посмотреть общий профиль всех медленных запросов:

# Rank Query ID           Response time  Calls R/Call V/M   Item
# ==== ================== ============== ===== ====== ===== ==============
#    1 0x67A347A2812914DF 440.2687 69.5%   119 3.6997  1.61 SELECT stats_min
#    2 0x0212FEF8C81EF1B6  78.2438 12.3%     8 9.7805 27.12 UPDATE files
#    3 0x2D2411FF42855142  67.4195 10.6%    10 6.7419 33.64 UPDATE projects
#    4 0xE5418AFB28BC18CF  25.1232  4.0%     7 3.5890  2.62 INSERT UPDATE files

Все запросы отсортированы по общему времени выполнения time. Оптимизировать запросы нужно в таком же порядке — это даст наибольший эффект. Кроме этого обратите внимание на колонку R/Call — там указано среднее время выполнения одного запроса. В примере у второго запроса это время больше 9 секунд, следует выяснить причины.

После этого в отчете можно увидеть детальный профиль каждого запроса:

# Query 1: 0.00 QPS, 0.00x concurrency, ID 0x67A347A2812914DF at byte 98907
# Scores: V/M = 1.61
# Time range: 2014-12-12 01:00:40 to 2015-02-03 01:01:22
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         77     119
# Exec time     69    440s      1s      9s      4s      8s      2s      2s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent     99 107.52M   1.19k   1.52M 925.21k   1.46M 565.37k 462.39k
# Rows examine  99 107.52M   1.19k   1.52M 925.21k   1.46M 565.37k 462.39k
# Query size     8   5.68k      46      54   48.89   51.63    1.51   49.17
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ================================================================
#  10s+

# Tables
#    SHOW TABLE STATUS FROM `t` LIKE 'stats_min'\G
#    SHOW CREATE TABLE `t`.`stats_min`\G
SELECT * FROM `stats_min`\G

# Converted for EXPLAIN
# EXPLAIN SELECT * FROM `stats_min`\G

Эти данные покажут детальное распределение ресурсов. Следует обратить внимание на Lock time, Rows sent, Rows examine. Чем больше эти значения, тем хуже.

И еще надо помнить, что в этот лог может попадать и запросы, которые отлично работают. Если сервер был загружен еще какими-то заданиями то запрос может выполняться дольше. После того как получили список запросов нужно анализировать их c помощью EXPLAIN.

Links:

devnotes.com.ua

ruhighload.com

Документация Percona Toolkit