Monday, July 16, 2012

Identifying MySQL slow queries

One of the most important steps in optimizing and tuning mysql is to identify the queries that are causing problems.
Some common questions in this environment are: How can we find out what queries are taking a long time to complete? How can we see what queries are slowing down the mysql server?

1. Activate the logging of mysql slow queries.

The first step is to make sure that the mysql server will log ‘slow’ queries and to properly configure what we are considering as a slow query.
First let’s check on the mysql server if we have slow query logging enabled:

mysqladmin var |grep log_slow_queries
| log_slow_queries                | OFF                          |

If log_slow_queries is ON then we already have it enabled. This setting is by default disabled – meaning that if you don’t have log_slow_queries defined in the mysql server config this will be disabled.
The mysql variable long_query_time (default 1) defines what is considered as a slow query. In the default case, any query that takes more than 1 second will be considered a slow query.
Ok, now for the scope of this article we will enable the mysql slow query log. In order to do to do this in your mysql server config file (/etc/my.cnf RHEL/Centos or /etc/mysql/my.cnf on Debian, etc.) in the mysqld section we will add:

long_query_time         = 1
log-slow-queries        = /var/log/mysql/mysql-slow.log

This configuration will log all queries that take more than 1 sec in the file /var/log/mysql/mysql-slow.log. You will probably want to define these based on your particular setup (maybe you will want the logs in a different location and/or you will consider a higher value than 1 sec to be slow query).
Once you have done the proper configurations to enable mysql to log slow queries you will have to reload the mysql service in order to activate the changes.

2. Investigate the mysql slow queries log:

After we enabled slow query logging we can look inside the log file for each slow query that was executed by the server. Various details are logged to help us understand how was the query executed:

Time: how long it took to execute the query
Lock: how long was a lock required
Rows: how many rows were investigated by the query (this can help see quickly queries without indexes)
Host: the actual host that launched the query (this can be localhost, or a different one in multiple servers setup)
The actual mysql query.

This information allows us to see what queries need to be optimized, but on a high traffic server and with lots of slow queries this log can grow up very fast making it very difficult to find any relevant information inside it.
In this case we have two choices:
We increase the long_query_time and we focus on the queries that take the most time to complete, and we gradually decrease this once we solve the queries.
We use some sort of tool to parse the slow query log file and have it show us the most used queries.
Of course based on the particular setup we might end up using both methods.

MySQL gives us a small tool that does exactly this: mysqldumpslow. This parses and summarizes the MySQL slow query log.
From the manual page here are the options we can use:

-v     verbose
-d     debug
-s=WORD, what to sort by (t, at, l, al, r, ar etc)
-r     reverse the sort order (largest last instead of first)
-t=NUMBER, just show the top n queries
-a     don't abstract all numbers to N and strings to 'S'
-n=NUMBER, abstract numbers with at least n digits within names
-g=WORD, grep: only consider stmts that include this string
-h=WORD, hostname of db server for *-slow.log filename (can be wildcard)
-i=WORD, name of server instance (if using mysql.server startup script)
-l     don't subtract lock time from total time

For example using:
mysqldumpslow -s c -t 10

In here we get the top 10 queries (-t 10) sorted by the number of occurrences in the log (-s c).

Now it is time to have those queries optimized. :)

Thanks to Billy G. and