When developing your own web application its important to make sure that pages load quickly. One of the biggest factors that determine page response times is the time taken to process SQL queries, but how do you know which SQL queries at fault?


The answer is MySQL's slow query log. By enabling this feature, a log file is created that will tell you each time a query takes too long to execute. You can then use this information to either optimize your database (typically adding the appropriate index) or rewrite the SQL.


Requirements

For this guide I will assume you already have an active MySQL or MariaDB installation, and are comfortable configuring your VPS over SSH. These instructions are based on Ubuntu 16.04 but the same approach works on other linux distributions.


Step 1: enable the Slow Query log

  1. First, determine where your MySQL configuration file "my.cnf" is located - on Ubuntu 16.04 it is /etc/mysql/my.cnf while on other distributions it is often /etc/my.cnf

  2. Edit the MySQL configuration file and add the following lines at the end: 

    [mysqld]
slow_query_log
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 1
log_queries_not_using_indexes

  3. Save your changes and restart MySQL 

    service mysql restart


Step 2: examining the slow query log

Start watching the slow log:

tail -f /var/log/mysql/slow.log


At startup, you will see output like this:

/usr/sbin/mysqld, Version: 5.7.12-0ubuntu1-log ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument


Now, using your browser start interacting with your web application and note the queries that are shown. Before long you may notice one or two queries that are consistently shown.


Start the MySQL client and run "EXPLAIN query" to determine the problem, and then either add indexes or rewrite the query as appropriate. If you have not used EXPLAIN before, see the next section.



Step 3: EXPLAIN query and add index

For demonstration purposes, here is a simple table with two columns "id" and "words". We will insert 1000 rows - the numbers from 1 to 1000, with each number spelt out in words:

cd /tmp ; wget https://gist.githubusercontent.com/nats/5cc184de1ff701183380c68e9dbf539e/raw/48b5e6daa9b87f411d97c07d9e626e79c88e3e8b/number-to-words.sh
mysql -u root -e 'create database test'
mysql -u root test -e 'create table test (id int, words varchar(100))'
for X in {1..1000} ; do mysql -u root test -e "insert into test values ($X, \"$(echo $X | bash number-to-words.sh | tail -1)\")" ; done


To give you an idea of the table structure, this is what the last few rows look like: 

mysql> select * from test order by id desc limit 5;
+------+---------------------+
| id   | words               |
+------+---------------------+
| 1000 | one zero zero zero  |
|  999 | nine nine nine      |
|  998 | nine nine eight     |
|  997 | nine nine seven     |
|  996 | nine nine six       |
+------+---------------------+
5 rows in set (0.00 sec)


If we now try to look up an entry: 

 mysql -u root test -e "select id from test where words = 'three four five '"
+------+
| id   |
+------+
|  345 |
+------+


And then check the slow log, we see the following addition: 

# Time: 2016-06-13T06:06:05.120842Z
# User@Host: root[root] @ localhost []  Id:  1092
# Query_time: 0.000792  Lock_time: 0.000228 Rows_sent: 1  Rows_examined: 1000
use test;
SET timestamp=1465797965;
select id from test where words = 'three four five ';


Note that Rows_examined is 1000 , meaning MySQL had to look at every row in my test table to find the answer. Now that we have identified a problem query we can explore the problem with MySQL client: 

mysql -u root test


Start by using "EXPLAIN" feature to see how a query is executed: 

mysql> explain select id from test where words = 'three four five ';
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | test  | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 1000 |    10.00 | Using where |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------------+
1 row in set, 1 warning (0.00 sec)


We can see here the key is NULL and rows is 1000, meaning that there was no index used and every row had to be examined. Lets fix that: 

mysql> create index ix_test_words on test(words);
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0


Finally, use "explain" to check how the query is performed after our change: 

mysql> explain select id from test where words = 'three four five ';
+----+-------------+-------+------------+------+---------------+---------------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key           | key_len | ref   | rows | filtered | Extra |
+----+-------------+-------+------------+------+---------------+---------------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | test  | NULL       | ref  | ix_test_words | ix_test_words | 103     | const |    1 |   100.00 | NULL  |
+----+-------------+-------+------------+------+---------------+---------------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.00 sec)


Now the key is ix_test_words and rows is 1, indicating that MySQL is using the new index to perform our query.