Database Journal
MS SQL Oracle DB2 Access MySQL PostgreSQL Sybase PHP SQL Etc SQL Scripts & Samples Tips Database Forum Rss Feed

» Database Journal Home
» Database Articles
» Database Tutorials
MS Access
SQL Scripts & Samples
» Database Forum
» Slideshows
Free Newsletters:

News Via RSS Feed

Rss Feed

Database Journal |DBA Support |SQLCourse |SQLCourse2

Featured Database Articles


Posted Mar 4, 2003

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

By Ian Gilfillan

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 []
# 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 []
# 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;
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

MySQL Archives

Latest Forum Threads
MySQL Forum
Topic By Replies Updated
MySQL in high availability and transction secure banking application klamor 1 August 28th, 10:24 AM
MySQL rollback UAL225 1 August 28th, 10:15 AM
Browsing a DB file that uses MySql finleytech 1 July 26th, 10:51 AM
php cookie won't pass variable to next page ITdevGirl 0 June 22nd, 12:13 PM