MySQL's Over-looked and Under-worked Slow Query Log

Tuesday Mar 4th 2003 by Ian Gilfillan
Share:

You say you've never heard of the Slow Query Log? That may be because it's de-activated by default. Following along with Ian Gilfillan, as he explores one of MySQL's less-used logs.

The slow query log is one of the less-used logs, as by default it's not activated, but it's a useful log for identifying queries that are not optimal. Often, in an under-performing system, especially with the default MyISAM tables (that make use of table-level locking, not row-level locking), a single query may be the cause of problems.

To activate the query log, simply place:
log-slow-queries = [slow_query_log_filename]
in your configuration file (my.cnf or my.ini), slow_query_log_filename being the optional filename for your log file. If you don't supply a filename, the default name will be used, which is the name of the host machine, with -slow.log being appended.

The slow query log logs all queries that take longer than long_query_time, which is usually 10 seconds by default (more than long enough for a self-respecting query to complete). You can alter the long_query_time in the configuration file. The following example sets the time to 5 seconds:
set-variable = long_query_time = 5
The slow query log can also optionally log all queries that don't use an index by placing the following in the configuration file:
log-long-format

Let's take a look at a sample slow query log:

/usr/local/mysql/libexec/mysqld, Version: 3.23.54-log, started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 030207 15:03:33
# User@Host: wsuser[wsuser] @ localhost.localdomain [127.0.0.1]
# Query_time: 13  Lock_time: 0  Rows_sent: 117  Rows_examined: 234
use wsdb;
SELECT l FROM un WHERE ip='209.xx.xxx.xx';

The first few lines simply contain version information, but the really useful data begins with the Time. This tells you what time the query completed. The next line contains user data, and the following how long the query took to run, how long it took to secure its locks, how many rows were sent back as a result, and how many rows were examined to determine the result. The final line before the actual query tells you which database was used. A discussion on optimizing queries is beyond the scope of this article, but you should know something about this before you can get the most out of the log. Otherwise, you may be able to identify the un-optimal queries, but not be able to do much with them. You should read the article Optimizing MySQL: Queries and Indexes if you are unclear about the topic.

Analyzing the slow query log

Analyzing the slow query log can be tricky, and you need to take care to avoid some basic pitfalls. The queries are written to the log after the query has been executed, and all locks released, which may be a different order to that in which they were run. The first query logged in the slow query log may be absolutely optimal, but have been delayed by a prior query, still running, that consumed most of the available resources. Have a look a little further in the log to see if you can identify a query that is the guilty one. Consider the following example (I've edited out some of the gumph):

# Time: 030207 15:03:33
# Query_time: 13  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
SELECT l FROM un WHERE ip='209.xx.xxx.xx';
# Time: 030207 15:03:42
# Query_time: 17  Lock_time: 1  Rows_sent: 0  Rows_examined: 0
SELECT l FROM un WHERE ip='214.xx.xxx.xx';
# Time: 030207 15:03:43
# Query_time: 57  Lock_time: 0  Rows_sent: 2117  Rows_examined: 4234
SELECT c,cn,ct FROM cr,l,un WHERE ci=lt AND lf='MP' AND ui=cu;

The example is fairly meaningless, but that should not distract you from the fact that the 3rd query ran for 57 seconds, and therefore began long before the first 2 queries in the log. The first 2 queries are more than likely innocent, but were affected by the 3rd query. Concentrating your efforts on optimizing the 3rd query is more likely to pay dividends.

Queries that are not optimal (as a result of misuse of indexes or poor application design) are by far the most common cause of MySQL performance problems. However, in many cases it's the server itself that cannot handle the load, and you should direct your attention elsewhere. Consider the following example:

/usr/local/mysql/libexec/mysqld, Version: 3.23.54-log, started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 030207 15:03:33
# User@Host: wsuser[wsuser] @ localhost.localdomain [127.0.0.1]
# Query_time: 13  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use wsdb;
SELECT l FROM un WHERE ip='209.xx.xxx.xx';
# Time: 030207 15:03:36
# User@Host: wsuser[wsuser] @ localhost.localdomain [127.0.0.1]
# Query_time: 14  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use wsdb;
SELECT l FROM un WHERE ip='201.xx.xxx.xx';

Looking at the queries alone, there doesn't seem to be much that can be done. From the Rows_examined and Rows_sent values, it seems that there is an index on the ip field, and the queries are as optimal as can be, yet they were both still slow. This seems to indicate that something else was wrong, and that the server as a whole was struggling. One clue here is that the user is connecting to localhost. If this is because the web server and the database server are on the same machine, it may finally be time to make the leap and separate the two machines. Being able to fine tune a server for database use only, or as a web server only, can make quite a noticeable difference. For more on this topic, read the article Optimizing MySQL: Hardware and the Mysqld Variables.

A tool that comes with the MySQL server, and used for displaying the results of a slow query log is mysqldumpslow. Simply use it with the name of the slow query log as the only parameter, for example:

% mysqldumpslow testhost-slow.log

There is some scope for more tools to enhance the usability of the slow query log. One I would find very useful, and always meant to write myself but haven't yet, would be a tool which re-orders the queries according to their start time, and not their completion time. If anyone is aware of such a tool, please let me know! One tool that I am aware of is the MySQL Slow Log Parser, written in Perl by Nathanial Hendler. This tool parses a MySQL slow_queries log file, ignoring all queries less than a value, $min_time, which you can set, and displays the number of times a query took more than this times to run. The queries are sorted by number of times this occurred, the most frequent occurrence appearing at last in the output. Queries are parsed so that 2 queries such as
SELECT * FROM offices WHERE office_id = 3;
and
SELECT * FROM offices WHERE office_id = 19;
are seen as one type of query, and become
SELECT * FROM offices WHERE office_id = XXX;

There is little excuse not to use the slow query log as it does not consume many resources, and is a useful tool for database administrators to keep a check on queries that themselves consume too much of the available resources.

» See All Articles by Columnist Ian Gilfillan

Share:
Home
Mobile Site | Full Site
Copyright 2017 © QuinStreet Inc. All Rights Reserved