Profiling MySQL Queries for Better Performance

At Pantheon, website performance is our priority, so when a client asked me to investigate why his site was slow, I decided to document the story to share with all of our users.

To begin, we must first define performance as response time. Keeping this in mind, a website with a higher response time can have multiple causes, starting from DNS issues, waiting for slow external services (various APIs, third party libraries), slow disk write operations, running crons on HTTP requests and ending with database problems. You can get a pretty good understanding of what’s going on by looking at the New Relic reports, which all Pantheon users can activate with a single click.

In this specific case, we realized something was up with the database, but unfortunately the New Relic version ran by the site didn’t tell us much. Your best friend in these situations is the MySQL slow query log. After downloading it, the first thing you should do is to generate a slow query digest using Percona Toolkit’s pt-query-digest tool. If you don’t have it installed already, I highly recommend it.

pt-query-digest mysql-slow-query.log > mysql-slow-query.digest.sql

This report is quite useful as it goes over the slow query log, analyzes each query, and then builds a report showing you the slowest queries—how many times they were executed, how many rows they scanned, the average and 95% percentile, the query size, etc. As you can see from the report I got, there was a single query responsible for roughly 99% of all response time (don’t be fooled as the slow query log only logs queries where the response time is higher than one second). This query was called 20,693 times.

# Profile

# Rank Query ID           Response time    Calls R/Call V/M   Item

# ==== ================== ================ ===== ====== ===== ============

#    1 0x88841BAD48A0CED7 67269.3309 99.1% 20693 3.2508  0.08 SELECT node taxonomy_term_data 

#    2 0xE469969EBDB2827C   257.3682  0.4%   116 2.2187  0.04 SELECT node location_instance 

#    3 0x2D2FEE92E4662103   118.8887  0.2%    63 1.8871  0.04 SELECT xmlsitemap

#    4 0x67A347A2812914DF   117.6174  0.2%    38 3.0952  5.45 SELECT cache_field

#    5 0x90F76EB1D74701D4   103.0260  0.2%    93 1.1078  0.01 SELECT node taxonomy_term_data 

#    6 0xD4C5D3B572DE5510    19.6973  0.0%    18 1.0943  0.00 SELECT node taxonomy_index

Scroll down or search by its ID 0x88841BAD48A0CED7 for a detailed view of it. The first thing I check is the Query_time distribution, which in this case seemed to be between 1 and 10 seconds—not that slow, but executed over 20,000 times it adds up. Since it’s a SELECT query there is virtually no locking going on, but I do see it is scanning through 1.46 million rows to only retrieve 10.

# Query 1: 0.24 QPS, 0.78x concurrency, ID 0x88841BAD48A0CED7 at byte 10783297

# Scores: V/M = 0.08

# Time range: 2015-08-17 09:08:17 to 2015-08-18 09:07:58

# Attribute    pct   total     min     max     avg     95%  stddev  median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count         98   20693

# Exec time     99  67269s      3s      7s      3s      4s   520ms      3s

# Lock time     99      3s   100us     1ms   164us   224us    42us   152us

# Rows sent      1 195.53k       0      10    9.68    9.83    1.52    9.83

# Rows examine  99  29.71G   1.47M   1.47M   1.47M   1.46M       0   1.46M

# Query size    99  19.10M     962     986  967.64  964.41      12  964.41

# String:

# Databases    pantheon

# Hosts        10.223.192.102 (10350/50%)... 1 more

# Users        pantheon

# Query_time distribution

#   1us

#  10us

# 100us

#   1ms

#  10ms

# 100ms

#    1s  ################################################################

#  10s+

SELECT DISTINCT node.nid AS nid, taxonomy_term_data_node.tid AS taxonomy_term_data_node_tid, location.city AS location_city

FROM 

node node

...

WHERE  ...

ORDER BY RAND() ASC

LIMIT 10

You can get a lot more information from this log, but for this use case it’s more than enough. You now know the specific query responsible for your site’s high response time, how many times it is executed, and that it scans through a lot of records to get a small result.

Next, we ran an EXPLAIN on it.

MariaDB [pantheon]> explain SELECT DISTINCT node.nid AS nid, taxonomy_term_data_node.tid AS taxonomy_term_data_node_tid, ...

+------+-------------+-------------------+--------+---------------------------------+

| id   | select_type | table             | rows   | Extra                           |

+------+-------------+-------------------+--------+---------------------------------+

|    1 | SIMPLE      | td                |      1 | Using temporary; Using filesort |

|    1 | SIMPLE      | tv                |      1 |                                 |

|    1 | SIMPLE      | tn                | 656908 | Using where                     |

|    1 | SIMPLE      | node              |      1 | Using where                     |

|    1 | SIMPLE      | location_instance |      1 |                                 |

|    1 | SIMPLE      | location          |      1 | Using where                     |

+------+-------------+-------------------+--------+---------------------------------+

The only thing that caught my eye in this explain was the first row Using temporary; Using filesort in the Extra column. It seems a temporary table was created and the “filesort algorithm” was used to sort the rows.

Warning

Although the name “filesort” may suggest that the temporary table was stored on disk, this isn’t necessarily the case. The name only refers to the sorting mechanism (which is actually a quicksort) and not to any temporary storage option (in memory or on disk). Read more about it in Baron Schwartz’s blog post.

So far, we know that the biggest problem with this query is that it’s executed a lot of times, it scans through a lot of rows, it creates at least one temporary table, and it has to sort a lot of rows. This could potentially happen on disk, but unfortunately we have no way of knowing from the EXPLAIN output. Let’s find all this out.

The next step is to connect to the actual MySQL server and run a few profiling techniques. These techniques are described in great detail in O’Reilly’s High Performance MySQL book, which I highly recommend reading.

I actually connected to the MySQL replica server to avoid impacting anything in the Live environment. If you have a replica, you should do the same.

The first step is to enable the profiling.

MariaDB [pantheon]> SET profiling = 1;

Now every query you run will get profiled and you can see what’s going on behind the scenes. After executing the query, you can run SHOW PROFILES and you’ll see a list of all your profiled queries.

MariaDB [pantheon]> SHOW PROFILES;

+----------+------------+-------------------------------------+

| Query_ID | Duration   | Query                                                                                                                                                                                                                                                                             |

+----------+------------+-------------------------------------+

|        1 | 2.74240657 | SELECT DISTINCT node.nid AS nid, ...|

+----------+------------+-------------------------------------+

1 row in set (0.00 sec)

Once this is done, you can check what MySQL actually did when this query was executed. As I was expecting, the highest duration was a process called Copying to tmp table. 

MariaDB [pantheon]> SHOW PROFILE FOR QUERY 1;

+--------------------------------+----------+

| Status                         | Duration |

+--------------------------------+----------+

| starting                       | 0.000021 |

| Waiting for query cache lock   | 0.000004 |

| checking query cache for query | 0.000151 |

| checking permissions           | 0.000008 |

| checking permissions           | 0.000002 |

| checking permissions           | 0.000002 |

| checking permissions           | 0.000002 |

| checking permissions           | 0.000001 |

| checking permissions           | 0.000004 |

| Opening tables                 | 0.000041 |

| After opening tables           | 0.000009 |

| System lock                    | 0.000005 |

| Table lock                     | 0.000004 |

| After table lock               | 0.000008 |

| init                           | 0.000076 |

| optimizing                     | 0.000046 |

| statistics                     | 0.000269 |

| preparing                      | 0.000035 |

| executing                      | 0.000003 |

| Creating tmp table             | 0.000032 |

| Copying to tmp table           | 2.740542 |

| Sorting result                 | 0.000576 |

| Sending data                   | 0.000046 |

| end                            | 0.000008 |

| removing tmp table             | 0.000349 |

| end                            | 0.000006 |

| query end                      | 0.000012 |

| closing tables                 | 0.000003 |

| removing tmp table             | 0.000004 |

| closing tables                 | 0.000020 |

| freeing items                  | 0.000015 |

| updating status                | 0.000037 |

| logging slow query             | 0.000054 |

| cleaning up                    | 0.000011 |

+--------------------------------+----------+

34 rows in set (0.00 sec)

You can see this information from the INFORMATION_SCHEMA table as well. Just run the query below.

MariaDB [pantheon]> SET @query_id = 1;

Query OK, 0 rows affected (0.00 sec)

MariaDB [pantheon]> SELECT STATE, SUM(DURATION) AS Total_R,

   ROUND(

   100 * SUM(DURATION) / (SELECT SUM(DURATION) FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = @query_id), 2

   ) AS Pct_R,

   COUNT(*) AS Calls,

   SUM(DURATION) / COUNT(*) AS "R/Call"

   FROM INFORMATION_SCHEMA.PROFILING

   WHERE QUERY_ID = @query_id

   GROUP BY STATE

   ORDER BY Total_R DESC;

+--------------------------------+----------+-------+-------+--------------+

| STATE                          | Total_R  | Pct_R | Calls | R/Call       |

+--------------------------------+----------+-------+-------+--------------+

| Copying to tmp table           | 2.740542 | 99.93 |     1 | 2.7405420000 |

| Sorting result                 | 0.000576 |  0.02 |     1 | 0.0005760000 |

| removing tmp table             | 0.000353 |  0.01 |     2 | 0.0001765000 |

| statistics                     | 0.000269 |  0.01 |     1 | 0.0002690000 |

| checking query cache for query | 0.000151 |  0.01 |     1 | 0.0001510000 |

| init                           | 0.000076 |  0.00 |     1 | 0.0000760000 |

| logging slow query             | 0.000054 |  0.00 |     1 | 0.0000540000 |

| optimizing                     | 0.000046 |  0.00 |     1 | 0.0000460000 |

| Sending data                   | 0.000046 |  0.00 |     1 | 0.0000460000 |

| Opening tables                 | 0.000041 |  0.00 |     1 | 0.0000410000 |

| updating status                | 0.000037 |  0.00 |     1 | 0.0000370000 |

| preparing                      | 0.000035 |  0.00 |     1 | 0.0000350000 |

| Creating tmp table             | 0.000032 |  0.00 |     1 | 0.0000320000 |

| closing tables                 | 0.000023 |  0.00 |     2 | 0.0000115000 |

| starting                       | 0.000021 |  0.00 |     1 | 0.0000210000 |

| checking permissions           | 0.000019 |  0.00 |     6 | 0.0000031667 |

| freeing items                  | 0.000015 |  0.00 |     1 | 0.0000150000 |

| end                            | 0.000014 |  0.00 |     2 | 0.0000070000 |

| query end                      | 0.000012 |  0.00 |     1 | 0.0000120000 |

| cleaning up                    | 0.000011 |  0.00 |     1 | 0.0000110000 |

| After opening tables           | 0.000009 |  0.00 |     1 | 0.0000090000 |

| After table lock               | 0.000008 |  0.00 |     1 | 0.0000080000 |

| System lock                    | 0.000005 |  0.00 |     1 | 0.0000050000 |

| Table lock                     | 0.000004 |  0.00 |     1 | 0.0000040000 |

| Waiting for query cache lock   | 0.000004 |  0.00 |     1 | 0.0000040000 |

| executing                      | 0.000003 |  0.00 |     1 | 0.0000030000 |

+--------------------------------+----------+-------+-------+--------------+

26 rows in set (0.01 sec)

This didn’t give us much information that we didn’t already know, but it did tell us that MySQL spent 99.93% of the total execution time copying to the temporary table.

It’s time for a different technique. I’m going to flush all the session variables from my current session, execute the query, and then check the variables again. When MySQL runs a query, depending on what it’s doing, various variables get incremented. Since it’s the only query that’s going to run, it gives you a pretty good idea of what’s going on.

MariaDB [pantheon]> FLUSH STATUS;

Query OK, 0 rows affected (0.01 sec)

MariaDB [pantheon]> SELECT DISTINCT node.nid AS nid, ...

MariaDB [pantheon]> SHOW STATUS WHERE Variable_name LIKE '%Handler%' OR Variable_name LIKE '%Created%';

+----------------------------+----------+

| Variable_name              | Value    |

+----------------------------+----------+

| Created_tmp_disk_tables    | 0        |

| Created_tmp_files          | 0        |

| Created_tmp_tables         | 2        |

| Handler_commit             | 1        |

| Handler_delete             | 0        |

| Handler_discover           | 0        |

| Handler_icp_attempts       | 0        |

| Handler_icp_match          | 0        |

| Handler_mrr_init           | 0        |

| Handler_mrr_key_refills    | 0        |

| Handler_mrr_rowid_refills  | 0        |

| Handler_prepare            | 0        |

| Handler_read_first         | 0        |

| Handler_read_key           | 1155718  |

| Handler_read_last          | 0        |

| Handler_read_next          | 770477   |

| Handler_read_prev          | 0        |

| Handler_read_rnd           | 10       |

| Handler_read_rnd_deleted   | 0        |

| Handler_read_rnd_next      | 1341     |

| Handler_rollback           | 0        |

| Handler_savepoint          | 0        |

| Handler_savepoint_rollback | 0        |

| Handler_tmp_update         | 0        |

| Handler_tmp_write          | 1340     |

| Handler_update             | 0        |

| Handler_write              | 0        |

| Innodb_pages_created       | 38426104 |

| Threads_created            | 51281    |

+----------------------------+----------+

29 rows in set (0.00 sec)

This gives us a few more details about what’s going on. For a full reference of these variables, visit MySQL's server status variables or MariaDB's server status variables.

As we already knew, a couple of temporary tables were created (see Created_tmp_tables), but these actually stayed in memory, as the variable Created_tmp_disk_tables is set to zero. That’s actually great news and you can also see how you might have gotten tricked by the “filesort” from the EXPLAIN we ran earlier.

[Related] Cassandra at Scale: The Problem with Secondary Indexes

The next good news is that both Handler_read_key and Handler_read_next have a high value. These indicate that the tables are properly indexed and that you are doing an index scan (as opposed to a full table scan).

I do see a few entries for Handler_read_rnd_next. When this value is high, it’s not a good sign and it generally means you are doing a lot of table scans or that your tables are not properly indexed.

Based on all this information, we are now able to conclude that the main reasons this query is slow are the copy to the temporary table and the filesort performed on it. Looking at the query itself, we can see the ORDER BY RAND() clause. Removing it and executing the query again leads to a response time of around 0.05 seconds. Compared to 4 - 5 seconds, that’s a 100x gain.

SELECT ... FROM  node … WHERE … ORDER BY RAND() LIMIT 10

Of course, sometimes removing the order by clause is not an option and you actually need a random list of items. Unfortunately MySQL (or other databases) doesn’t have a good solution for this. Ordering by random and limiting the result works for small data sets, but produces full table scans. For higher data sets, it will in time slow down your site.

This is a known anti-pattern that you should avoid it at all costs. It is described in greater detail in Bill Karwin’s SQL Antipatterns book, in which the proposed solutions either work with the primary key (get a random value between 1 and MAX(primary key)) or select the random data set from the the OFFSET (LIMIT 10 OFFSET $random_offset). These all have advantages and disadvantages, some of them create random IO, but they avoid full table scans and sorting.

One thing to keep in mind is that the first profiling technique (SET profiling = 1) is deprecated in MySQL 5.7 will most likely be removed in future versions of MySQL. As an alternative, the performance_schema table will have to be used instead.