How to Enable MySQL’s Slow Query Log


Graphic showing the MySQL logo

Unexpectedly slow queries are one of the most common MySQL performance issues. A query that performs acceptably in development can falter when stressed by a production workload.

Large applications might run hundreds of unique database queries each time an endpoint is hit. This makes it difficult to single out the queries that are causing delays in the server’s response. The MySQL slow query log is a debugging option which can help you identify suspect SQL statements, providing a starting point for your investigations.

Enabling the Slow Query Log

The log is a built-in mechanism for recording long-running SQL queries. Queries that don’t complete within a configured time will be written into the log. Reading the log’s contents shows you the SQL that was executed and the time taken.

Slow query logging is turned off by default. You can activate it on your server by running the following command from an administrative MySQL shell:

SET GLOBAL slow_query_log_file="/var/log/mysql/mysql-slow.log";
SET GLOBAL slow_query_log=1;

The change applies immediately. Slow queries will now be logged to /var/log/mysql/mysql-slow.log. You can review this file periodically to identify poorly performing queries.

MySQL counts a query as “slow” if it takes over 10 seconds to complete. This limit is usually too relaxed for user-facing web applications where near-instant responses are expected. You can change the limit by setting the long_query_time variable:

SET GLOBAL long_query_time=1;

The value sets the minimum duration for slow queries. It’s important to find a balance that suits your own application. Too high a threshold will exclude queries that are actually impacting performance. Conversely, very low values can cause too many queries to be captured, creating an excessively noisy log.

Using MySQL’s Configuration File

You should enable the slow query log in your MySQL configuration file if you plan to use it long-term. This will ensure logging’s resumed automatically after the MySQL server restarts.

The config file’s location can vary by platform distribution. It’s usually at /etc/mysql/my.cnf or /etc/mysql/mysql.conf.d/mysqld.cnf. Add the following lines to replicate the settings that were dynamically enabled above:

slow_query_log=1
slow_query_log_file=/var/log/mysql/mysql-slow.log
long_query_time=1

Restart MySQL to apply your changes:

$ sudo service mysql restart

The slow query log will now be active each time the MySQL server starts.

Customizing Log Content

The log normally only includes SQL queries that exclude the “slow” threshold and have been submitted by client applications. This excludes any slow administrative operations that may occur, such as index creations and table optimizations, as well as queries that have the potential to be slow in the future.

You can extend the log to include this information by making the following changes to your config file:

  • log_slow_admin_statements = 1 – Includes administrative SQL statements such as ALTER TABLE, CREATE INDEX, DROP INDEX, and OPTIMIZE TABLE. This is rarely desirable as these operations are usually run during maintenance and migration scripts. Nonetheless this setting can be helpful if your application also dynamically performs these tasks.
  • log_slow_replica_statements = 1 – This setting enables slow query logging for replicated queries on replica servers. This is disabled by default. Use log_slow_slave_statements instead for MySQL versions 8.0.26 and older.
  • log_queries_not_using_indexes = 1 – When this setting is enabled, queries which are expected to retrieve all the records from the target table or view will be logged, even if they didn’t exclude the slow query threshold. This can help identify when a query is missing an index or is unable to use it. Queries that have an index available will still be logged if they lack constraints that limit the number of fetched rows.

Logging queries that aren’t using indexes can significantly increase verbosity. There may be situations in which a full index scan is expected or necessary. These queries will keep showing up in the log even though they can’t be resolved.

You can rate limit queries without indexes by setting the log_throttle_queries_not_using_indexes variable. This defines the maximum number of logs that will be written in a 60-second period. A value of 10 means up to 10 queries will be recorded per minute. After the tenth event, no more queries will be logged until the next 60-second window opens.

Interpreting the Slow Query Log

Each query that makes it into the slow query log will display a set of lines that look similar to the following:

# Time: 2022-07-12T19:00:00.000000Z
# User@Host: demo[demo] @ mysql [] Id: 51
# Query_time: 3.514223  Lock_time: 0.000010  Rows_sent: 5143  Rows_examined: 322216
SELECT * FROM slow_table LEFT JOIN another_table ...

The commented lines above the query contain the time at which it executed, the MySQL user that the client connected as, and statistics providing the duration and number of rows sent. The above example took 3.5 seconds to complete and looked at over 320,000 rows, before sending only 5,143 to the client. This could be an indication that missing indexes are causing MySQL to inspect too many records.

You can optionally include more information in the log by setting the log_slow_extra = 1 system variable in your config file. This will add the thread ID, number of bytes received and sent, and the number of rows considered for sorting, as well as statement-specific request counts that provide visibility into how MySQL handled the query.

The log file must be treated with care as its contents will be sensitive. Queries are displayed in full, without any masking of parameter values. This means user data will be present if you’re using the slow query log on a production server. Access should be restricted to the developers and database administrators who are tuning the SQL statements.

Slow Query Logging and Backups

One common frustration with the slow query log arises when you’re also using MySQLDump to create database backups. Long-running SELECT * FROM ... queries will be executed to fetch the data from your tables and feed them into your backup. They’ll be included in the slow query log like any other SQL statement. This can pollute the log if you’re making backups regularly.

You can address this by temporarily disabling the slow query log before you run mysqldump. You can reactivate the log after the backup completes. Adjust your backup script so it looks similar to the following:

#!/bin/bash

# Temporarily disable slow query logging
mysql -uUser -pPassword -e "SET GLOBAL slow_query_log=0";

# Run mysqldump
mysqldump -uUser -pPassword --single-transaction databaseName | gzip > backup.bak

# Enable the slow query log again
mysql -uUser -pPassword -e "SET GLOBAL slow_query_log=1"

This will keep MySQLDump activity out of the slow query log, making it easier to focus on the SQL that’s executed by your application.

Summary

The MySQL slow query log is one of the most effective ways to pinpoint the cause of performance issues. Begin by estimating the delay you’re experiencing and use this value as your long_query_time. Reduce the value if nothing shows up in the log after you’ve reproduced the problem.

The slow query log won’t tell you exactly how to fix the slowdown. However the ability to view the exact SQL received by the server lets you repeat poorly performing statements and then gauge the effect of optimizations. Adding an index or missing constraint can be the difference between a query that touches thousands of rows and one that works with a handful.





Source link