DB-유

Enabling and Reading the MySQL Slow Query Log

· mysql, performance, logging

"The database feels slow" is the most useless bug report I get, and the slow query log is the first thing I open when I get one. It records every statement over a threshold, with lock time, rows examined and rows sent. Unlike SHOW PROCESSLIST it catches the 400 ms queries that never show up while you're staring at the screen but add up to a saturated server. It's in every MySQL and MariaDB version and costs little when configured sensibly. Here is how I set it up on 5.6/5.7.

Turn it on at runtime

No restart needed. From a session with SUPER:

SET GLOBAL slow_query_log_file = '/var/log/mysql/mysql-slow.log';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_output = 'FILE';
SET GLOBAL slow_query_log = ON;

long_query_time accepts fractions, so 0.5 is valid. Note that the new threshold applies only to sessions opened after the change; existing connections keep the old value.

Make sure the directory exists and is writable by the mysql user first:

sudo mkdir -p /var/log/mysql
sudo chown mysql:mysql /var/log/mysql

Make it survive a restart

Add the same settings to the server section of your config, /etc/my.cnf on CentOS or /etc/mysql/mysql.conf.d/mysqld.cnf on Ubuntu:

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 0
log_slow_admin_statements = 1
log_slow_slave_statements = 1
min_examined_row_limit = 0

I leave log_queries_not_using_indexes off by default. On most applications it floods the log with tiny lookups on 20-row tables that are perfectly fine without an index. If you do turn it on, pair it with log_throttle_queries_not_using_indexes = 10 (5.6.5 and later) to cap the noise per minute.

Reading one entry

A typical record:

# Time: 2017-06-27T22:14:03.512345Z
# User@Host: shopapp[shopapp] @  [10.0.1.23]  Id:  8812
# Query_time: 2.417831  Lock_time: 0.000112 Rows_sent: 25  Rows_examined: 1893422
SET timestamp=1498601643;
SELECT o.id, o.total FROM orders o WHERE o.customer_email = 'x@example.com' ORDER BY o.created_at DESC LIMIT 25;

The ratio between Rows_examined and Rows_sent is the key number. Scanning 1.9 million rows to return 25 tells you an index on customer_email (or customer_email, created_at) is missing. High Lock_time with a low Query_time points at contention rather than at the query itself.

Quick summary with mysqldumpslow

The log gets big fast. mysqldumpslow ships with the server and groups similar queries by replacing literals with N and 'S':

sudo mysqldumpslow -s t -t 10 /var/log/mysql/mysql-slow.log

-s t sorts by total time, -s c by count, -s at by average time; -t 10 shows the top ten. The output gives count, total and average time and a normalized version of the statement.

pt-query-digest is better

Percona Toolkit's pt-query-digest gives a far more useful report, with percentiles and the worst example for each fingerprint. I install it on every database host:

sudo yum install -y https://www.percona.com/downloads/percona-release/redhat/0.1-4/percona-release-0.1-4.noarch.rpm
sudo yum install -y percona-toolkit
pt-query-digest /var/log/mysql/mysql-slow.log > /tmp/slow-report.txt
less /tmp/slow-report.txt

To limit the analysis to a time window:

pt-query-digest --since '2017-06-27 20:00:00' --until '2017-06-27 23:00:00' /var/log/mysql/mysql-slow.log

The profile section at the top lists each query class with its share of total response time. I usually fix the top three and re-measure the following day.

Rotate it

Add a logrotate rule or the file grows forever (I learned that from a full /var). The rule below reopens the log with FLUSH SLOW LOGS; copytruncate is the alternative:

/var/log/mysql/mysql-slow.log {
    daily
    rotate 14
    missingok
    compress
    delaycompress
    notifempty
    create 640 mysql mysql
    postrotate
        /usr/bin/mysql -e 'FLUSH SLOW LOGS' 2>/dev/null || true
    endscript
}

FLUSH SLOW LOGS exists since 5.5; on older releases use FLUSH LOGS. The mysql command in postrotate needs credentials, typically from a root ~/.my.cnf.

Check it

SHOW GLOBAL VARIABLES LIKE 'slow_query%';
SHOW GLOBAL VARIABLES LIKE 'long_query_time';
SELECT SLEEP(2);

The SLEEP(2) should appear in the log within a second. SHOW GLOBAL STATUS LIKE 'Slow_queries' gives a running count since the server started, which is a cheap way to graph slow query rate in your monitoring.

Gotchas

  • Nothing is written although slow_query_log is ON – Check log_output. If it is TABLE, entries go to mysql.slow_log instead of the file; query it with SELECT * FROM mysql.slow_log ORDER BY start_time DESC LIMIT 10; or set it back to FILE.
  • [ERROR] Could not use /var/log/mysql/mysql-slow.log for logging (error 13 - Permission denied) – Directory ownership, or on CentOS SELinux. Fix with chown mysql:mysql and, if SELinux is enforcing, semanage fcontext -a -t mysqld_log_t '/var/log/mysql(/.*)?' followed by restorecon -Rv /var/log/mysql.
  • Queries you know are slow do not show up – The session was opened before you changed long_query_time, or the query is fast per execution but called thousands of times. For the second case, lower the threshold to 0 for a few minutes during a quiet period and use pt-query-digest, then raise it again.
  • Log file becomes gigabytes per hour – Threshold too low or log_queries_not_using_indexes on. Raise long_query_time or enable throttling as described above.