Finding slow MySQL queries

March 21, 2019

tl;dr

code

SELECT @@GLOBAL.slow_query_log, @@GLOBAL.long_query_time, @@GLOBAL.slow_query_log_file;

Check if logging is already on

By default the slow query log is disabled, it comes with a performance hit.

code

-- get all glbal variables
SHOW GLOBAL VARIABLES;

-- get values for specific variables
SHOW GLOBAL VARIABLES LIKE 'long_query_time';
-- or
SELECT @@GLOBAL.long_query_time;

-- get Slow Query related values
SELECT @@GLOBAL.slow_query_log, @@GLOBAL.long_query_time, @@GLOBAL.slow_query_log_file;

From within mysql

code

-- Enable logging
SET GLOBAL slow_query_log = 'ON';

-- decide how many seconds determine a long query (X seconds)
SET GLOBAL long_query_time = X;

-- set log file path
SET GLOBAL slow_query_log_file = '/path/filename';

If you want queries longer than 10 seconds to be logged, you need to disable log_queries_not_using_indexes, which causes queries quicker than 10 seconds to be logged if they are not using an index for row lookups in the statements written to slow query log.

code

SELECT @@GLOBAL.log_queries_not_using_indexes;

SET GLOBAL log_queries_not_using_indexes = 'OFF';

Empty the log file

code

> hostname-slow.log

GLOBAL vs SESSION

If you are not seeing any results, it could be that you updated the GLOBAL variables (that only apply when you reconnect) instead of SESSION variables (that are for current session)

code

SHOW SESSION VARIABLES LIKE "long_query_time";
SHOW GLOBAL VARIABLES LIKE "long_query_time";
SHOW VARIABLES LIKE "long_query_time";

pt-query-digest

code

cd
curl -LO https://percona.com/get/pt-query-digest
chmod +x pt-query-digest
./pt-query-digest /var/lib/mysql/*-slow.log

code

# Query 15: 2.50 QPS, 0.00x concurrency, ID 0x9E26938B15493109AAFED97F2F8963F5 at byte 6309295
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2019-03-21 12:37:41 to 12:45:07
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          8    1116
# Exec time      0      1s   927us     8ms     1ms     1ms   237us     1ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent     34  49.04k      45      45      45      45       0      45
# Rows examine   0 252.84k     232     232     232     232       0     232
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    24   3.28M   2.98k   3.02k   3.01k   2.89k       0   2.89k
# Query size     0  92.53k      83      86   84.90   84.10    1.50   84.10
# String:
# Databases    dating
# Hosts        10.0.113.11 (558/50%), 10.0.113.12 (558/50%)
# Last errno   0
# Users        fppuser
# Query_time distribution
#   1us
#  10us
# 100us  #
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
call `dating`.`GetUserSelectedAttributes` (343297, 'USER_IDEAL', @_cnet_param_OPCount)\G

mysqldumpslow

you can use the mysqldumpslow command to process a slow query log file and summarize its contents.

code

# use mysqldumpslow to sort the log file (prints to stdout by default)
mysqldumpslow -a -s t

Sort -s options: -c is count, -t is time, -at is avergae time (default), -l is lock time, -al is avg. lock time, -r is rows sent and -ar is avg. rows sent

-r will reverse any sort order that you specify.

NOTE: This disn't work for me, it'd just show all time values as 0.0

Finding slow MySQL queries

GLOBAL vs SESSION

pt-query-digest

mysqldumpslow

Links