MySQL's slow query log is a key component in your MySQL administration setup. Whilst normal logging can help you in terms of tracking down issues with your database system, the slow query log can help you track down issues in your database setup before they become problematic.
Getting the slow query log set up correctly can help you find and solve issues with slow database queries before they become more problematic. Most slow queries will work fine when there's just a few rows, but as your data grows so will the time taken to find the data. Having the slow query log in place will show these queries and help you do something about them.
In this article we'll look at how to set up the slow query log, how to analyse the results and also an exercise in triggering the slow query log with real data. All of this information will also work with MariaDB in the same way.
Slow Query Log Options
There are a few options associated with the slow query log.
- slow_query_log - A boolean flag that turns the slow query log on or off.
- slow_query_log_file - The location of the slow query log.
- long_query_time - The number of seconds that must elapse in order to trigger the slow query log.
- min_examined_row_limit - The minimum number of rows that must be examined in order to trigger the slow query log.
- log_slow_admin_statements - A boolean flag that can be used to prevent administrative queries from being recorded in the slow query log.
- log_queries_not_using_indexes - A boolean flag that will prevent the slow query log being triggered if the query is not using indexes.
These can be set in the MySQL or MariaDB configuration files. Here is a typical configuration setup that will trigger the slow query log if a query takes longer than 2 seconds, and record that data in the file "/var/log/mysql-slow.log".
; Activate the slow query log.
slow_query_log = ON
; Set the location of the slow query log.
slow_query_log_file = /var/log/mysqld-slow.log
; Set the timeout (in seconds) that will trigger the slow query log.
long_query_time = 2
; The minimum number of rows that will trigger the slow query log.
min_examined_row_limit = 2
; Flag to log administration statements that might pollute the slow query log.
log_slow_admin_statements = OFF
; Flag to log queries that do not use indexes
log_queries_not_using_indexes = ON
It is best to configure it in these settings in the configuration files and then tweak it as required using the SET command within your database. Using the GLOBAL keyword will set these configuration items for all new sessions on the server.
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL slow_query_log_file = '/var/log/mysqld-slow.log';
SET GLOBAL long_query_time = 2;
If you want to see what the values in your system are already then you can use the SHOW command, passing in the value you want to find.
SHOW GLOBAL VARIABLES LIKE 'slow_query%';
This will print out the following.
+---------------------+--------------------------+
| Variable_name | Value |
+---------------------+--------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysqld-slow.log |
+---------------------+--------------------------+
With that in place let's look at the slow query log itself.
Analysing The Slow Query Log
With the slow query log recording data you can just print it out to see what it has in it.
Whilst this will show you queries that have triggered the log, it isn't the best approach. A much better way of inspecting the slow query log is to use the mysqldumpslow tool.
To use the mysqldumpslow tool just pass in the slow query log.
mysqldumpslow /var/log/mysqld-slow.log
This will read the slow query log and show you a synopsis of the queries that triggered the log to run.
For example, here is a record from a slow query log that took the server 7.9 seconds to run and looked at 1000 rows.
Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 1 Time=7.90s (7s) Lock=0.00s (0s) Rows_sent=6042.0 (6042), Rows_examined=10000.0 (10000), Rows_affected=0.0 (0), root[root]@localhost
SELECT *
FROM users AS u
LEFT JOIN club_members AS cm ON u.id = cm.user_id
LEFT JOIN clubs AS c ON cm.club_id = c.id
WHERE cm.user_id IS NULL
In order for this query to have been logged here the time long_query_time option must be set to less than 7 seconds and the min_examined_row_limit option must be set to less than 10000 rows. The "Count" here is the number of times that the query has been run. The log also shows us the user that generated the query, but not the database in which the query was run.
You can get the tool to generate a "top" list of the worse performing queries with the -t flag. This will show the top 5 slowest queries based on the average query time.
mysqldumpslow -t 5 /var/log/mysqld-slow.log
You can also use the -s flag to sort the top slowest queries by different values, here we are telling the tool to sort by the raw query time.
mysqldumpslow -t 5 -s t /var/log/mysqld-slow.log
Values that can be used with the -s flag are:
- t - Query time.
- l - Lock time (lower case L).
- r - Rows sent.
- at - Average query time (this is the default value).
- al - Average lock time.
- ar - Average rows sent.
Using this tool allows us to quickly inspect the query log and see the worst offenders.
Triggering The Slow Query Log
Now that we have setup the slow query log I wanted to have a reliable way of triggering it. I have seen people asking how to trigger the slow query log before and I haven't seen a decent response to the question. In fact, the usual response is to make the database server sleep for a few seconds, using the sleep function, like this.
SELECT SLEEP(10);
Although this query does trigger the slow query log, it doesn't allow us to see any useful information about the query, or see how fixing issues can dramatically speed up queries.
To this end I created a slow query exercise that generates 25,000 records of data in a database (across three tables) that contains no indexes. All you need to run this exercise is a MySQL/MariaDB server and PHP (to generate the data). The Faker project was used to generate all the data so that it didn't look too random and make it easier to work with.
The database itself is a normalised club management system with three tables.
- users - The list of users.
- clubs - The list of clubs.
- club_members - Stores the relationship between users and clubs.
To create the data for the tables you need to run "composer install" in the project to install the Faker package followed by "php faker.php" to generate the required CSV files that contain the data.
This will generate 10,000 user and club records, and half the number of users as club member records, so that some of the users will not be part of groups. Settings things up this way allows us to perform some different queries to find users who are both in clubs and not in clubs.
Once the CSV files have been generated we can create the database and import them into the created tables. There are two helper scripts that assist with the import process.
- slow_setup.sql - Will generate a database and tables without any indexes and then import the data into them.
- optimized_setup.sql - Will generate a database and tables with the needed indexes and then import the data into them.
The idea is to run the slow_setup.sql script to run some queries that are slow in order to trigger the slow query log. After that the optimized_setup.sql can be run to import the properly indexed version of the tables and see how this improves the speed of the queries.
To run the scripts just run "mysql" with the needed authentication and pass in the appropriate script file. The user must be able to create databases and tables in order to perform the needed steps.
To import the slow setup run the following.
mysql -u root -p < slow_setup.sql
The tables that this will create look like the following.
CREATE TABLE `users` (
id INT,
forename VARCHAR(255) NOT NULL,
surname VARCHAR(255) NOT NULL
);
CREATE TABLE `clubs` (
id INT,
name VARCHAR(255) NOT NULL
);
CREATE TABLE `club_members` (
user_id INT,
club_id INT
);
If you know much about MySQL databases then you'll see the issue here, but the purpose of the slow setup is to allow the slow query log to be triggered.
The data is then imported into the tables using the following SQL.
LOAD DATA LOCAL INFILE 'users.csv'
INTO TABLE `users`
FIELDS TERMINATED BY ','
LINES TERMINATED BY '\n';
LOAD DATA LOCAL INFILE 'clubs.csv'
INTO TABLE `clubs`
FIELDS TERMINATED BY ','
LINES TERMINATED BY '\n';
LOAD DATA LOCAL INFILE 'club_members.csv'
INTO TABLE `club_members`
FIELDS TERMINATED BY ','
LINES TERMINATED BY '\n';
With the database set up we can then look at running a query. The following query will generate a list of all of the users who are members of clubs.
SELECT *
FROM users AS u
INNER JOIN club_members AS cm ON u.id = cm.user_id
INNER JOIN clubs AS c ON cm.club_id = c.id;
This query, whilst simple, takes over 5 seconds to run. I have tested this with 100,000 records and this query takes at least 10 minutes to complete with that amount of data.
If this was a real world example then the database would probably have been fine to begin with, but would have gotten slower and slower as more data was added. The slow query log is useful to setup before you encounter performance issues as it will warn you when the amount of data becomes a problem.
When we run a query this slow we should be able to see it in the slow query log, which we can, here's the section from the slow query log.
> mysqldumpslow /var/log/mysqld-slow.log
Count: 2 Time=5.22s (10s) Lock=0.00s (0s) Rows_sent=5001.0 (10002), Rows_examined=5001.0 (10002), Rows_affected=0.0 (0), root[root]@localhost
SELECT * FROM users AS u INNER JOIN club_members AS cm ON u.id = cm.user_id INNER JOIN clubs AS c ON cm.club_id = c.id
To see why a query is running slow we need to use the EXPLAIN command. This is added to the start of the query and will show us what happens when the query is run and gives us the following output.
> EXPLAIN SELECT * FROM users AS u INNER JOIN club_members AS cm ON u.id = cm.user_id INNER JOIN clubs AS c ON cm.club_id = c.id;
+------+-------------+-------+------+---------------+------+---------+------+-------+--------------------------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------+------+---------------+------+---------+------+-------+--------------------------------------------------------+
| 1 | SIMPLE | cm | ALL | NULL | NULL | NULL | NULL | 5001 | |
| 1 | SIMPLE | c | ALL | NULL | NULL | NULL | NULL | 10029 | Using where; Using join buffer (flat, BNL join) |
| 1 | SIMPLE | u | ALL | NULL | NULL | NULL | NULL | 10072 | Using where; Using join buffer (incremental, BNL join) |
+------+-------------+-------+------+---------------+------+---------+------+-------+--------------------------------------------------------+
3 rows in set (0.011 sec)
It's worth understanding everything the explain command shows you, but it's clear here that because we don't have any keys we are loading all rows in all tables to perform this query. The database server has to jump through a number of steps in order to analyse this data on the fly, which causes massive slow down when generating the results.
To fix this we need to create tables that have indexes. we do this by making each ID a primary key (which is itself an index) and by adding a full text index to the forename and surname fields. Here is the table structure that is imported via the optimized_setup.sql script.
CREATE TABLE `users` (
id INT PRIMARY KEY,
forename VARCHAR(255) NOT NULL,
surname VARCHAR(255) NOT NULL,
FULLTEXT (forename, surname)
) ENGINE=InnoDB;
CREATE TABLE `clubs` (
id INT PRIMARY KEY,
name VARCHAR(255) NOT NULL,
FULLTEXT (name)
) ENGINE=InnoDB;
CREATE TABLE `club_members` (
user_id INT,
club_id INT,
INDEX (user_id, club_id)
) ENGINE=InnoDB;
Now, when we run the query to get a list of the users and clubs it takes well under a second. Passing the query through the explain command shows us a much more efficient use of indexes and data in the tables to generate the results.
> EXPLAIN SELECT * FROM users AS u INNER JOIN club_members AS cm ON u.id = cm.user_id INNER JOIN clubs AS c ON cm.club_id = c.id;
+------+-------------+-------+--------+---------------+---------+---------+------------------+------+--------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------+--------+---------------+---------+---------+------------------+------+--------------------------+
| 1 | SIMPLE | cm | index | user_id | user_id | 10 | NULL | 5001 | Using where; Using index |
| 1 | SIMPLE | c | eq_ref | PRIMARY | PRIMARY | 4 | clubs.cm.club_id | 1 | |
| 1 | SIMPLE | u | eq_ref | PRIMARY | PRIMARY | 4 | clubs.cm.user_id | 1 | |
+------+-------------+-------+--------+---------------+---------+---------+------------------+------+--------------------------+
3 rows in set (0.001 sec)
After creating the optimised tables and importing the data the database is now usable. Even with 100,000 records the results are returned in under a second. This clearly shows the importance of indexes and demonstrates the use of the slow query log and explain commands to spot performance problems in your databases.
Conclusion
The slow query log is a powerful tool to spot performance problems in your databases, but it's important to get things setup before you run into any problems. If you don't then there's a chance that your entire application will be incredibly slow without you spotting it. The log itself will just show you where the problem queries are, you'll have to do some detective work to figure out why the queries are slow and what you can do about them.
Be careful of false positives as well. Some queries will be slow because they are performing complex operations and so should be excluded from your analysis.
I hope that by running through the slow query exercise that you can get the feel of the slow query log and make better use of it in the future.
The slow query log can be configured beyond what has been described here. Both MySQL and MariaDB have different properties that can be set to alter how the slow query log can be used.
Add new comment