MJ Convento

/

EXPLAIN, and the report that took forty seconds

2,034 words, about 9 min read

The collections report took 41 seconds. It runs twice a day, every working day since August, and the finance team had stopped complaining about it, which is worse than complaining. They had learned to open the page, go and make coffee, and come back. I can give you the number to six decimal places because the query eventually landed in the slow query log, which is where this started.

The ERP runs on MySQL 5.5 with InnoDB, one server, no replica. The report is two queries against an invoice table of about 1.9 million rows, joined to customer. It took me four days to make it fast, and two of those days were spent being confidently wrong, which is the part worth writing down.

The slow query log, and why it stayed empty

I had never turned the slow query log on. The manual says the minimum and default values of long_query_time are 0 and 10, that the value can be specified to a resolution of microseconds, and that the log is disabled by default. So:

SET GLOBAL slow_query_log = 1;
SET GLOBAL long_query_time = 1;

Then nothing appeared for twenty minutes, and I assumed I had set it wrong. I had not. long_query_time has a session value as well as a global one, and our connections are persistent, so every existing connection kept the old value of 10 until the pool recycled. A query taking 41 seconds should have crossed 10 seconds anyway, and it did, once the first connection was new enough to have picked up the file destination. Both things had to line up before I saw an entry.

# Time: 141202 14:07:51
# User@Host: erp_app[erp_app] @ appserver [10.0.2.14]
# Query_time: 41.246516  Lock_time: 0.000132 Rows_sent: 63  Rows_examined: 1921664
SET timestamp=1417500471;
SELECT c.name, COUNT(*) AS invoices, SUM(i.total) AS amount
FROM invoice i
JOIN customer c ON c.id = i.customer_id
WHERE i.branch_id = 4
  AND i.status = 'posted'
  AND DATE(i.issued_at) BETWEEN '2014-11-01' AND '2014-11-30'
GROUP BY c.id, c.name
ORDER BY amount DESC;

63 rows sent, 1,921,664 rows examined. That ratio is the whole article. mysqldumpslow -s t sorted the log by query time and put this one at the top with nothing else close, which at least meant I was not going to waste a week on the wrong query.

What EXPLAIN said

mysql> EXPLAIN SELECT c.name, COUNT(*) AS invoices, SUM(i.total) AS amount
    -> FROM invoice i JOIN customer c ON c.id = i.customer_id
    -> WHERE i.branch_id = 4 AND i.status = 'posted'
    ->   AND DATE(i.issued_at) BETWEEN '2014-11-01' AND '2014-11-30'
    -> GROUP BY c.id, c.name ORDER BY amount DESC;
+----+-------------+-------+--------+---------------+---------+---------+-------------------+---------+----------------------------------------------+
| id | select_type | table | type   | possible_keys | key     | key_len | ref               |    rows | Extra                                        |
+----+-------------+-------+--------+---------------+---------+---------+-------------------+---------+----------------------------------------------+
|  1 | SIMPLE      | i     | ALL    | idx_status    | NULL    |    NULL | NULL              | 1921664 | Using where; Using temporary; Using filesort |
|  1 | SIMPLE      | c     | eq_ref | PRIMARY       | PRIMARY |       4 | erp.i.customer_id |       1 |                                              |
+----+-------------+-------+--------+---------------+---------+---------+-------------------+---------+----------------------------------------------+

Four things in one screen. type is ALL, a full scan of every invoice we have ever issued. possible_keys names idx_status, the one index anybody had bothered to add, but key is NULL, so the optimizer looked at it and said no. That is the documented behaviour: when there is a choice, MySQL normally uses the index that finds the smallest number of rows, and status = 'posted' matches about 1.7 million of our 1.9 million invoices. Reading 1.7 million index entries and then chasing each one back to its row is worse than reading the table start to finish. I did not believe this, added FORCE INDEX (idx_status) out of spite, and got 58 seconds instead of 41. Index hints are a way to prove the optimizer right.

Then the Extra column, which the manual tells you to read first: if you want your queries to be fast, look out for Using filesort and Using temporary. Both are here, and neither means what I thought it meant. Using filesort does not mean a file on disk. It means MySQL must do an extra pass, storing sort keys and row pointers for every matching row and then sorting them, because no index can deliver the rows already ordered. Using temporary means a temporary table has to be built to hold the result, which typically happens when the query groups by one thing and orders by another. Ours groups by customer and orders by a sum, so no index in the world removes that one.

The index that was never used

My first move was the obvious one. There is a date range in the WHERE clause, so index the date:

CREATE INDEX idx_invoice_issued_at ON invoice (issued_at);

The plan did not change. Not the rows, not the type, not even possible_keys: the new index did not appear there at all. It sat in the table taking up space and taking a write on every insert, and no query ever touched it.

The reason is DATE(i.issued_at). A B-tree index is usable for comparisons on the column with =, >, >=, <, <= or BETWEEN, and for LIKE against a constant that does not start with a wildcard. DATE(i.issued_at) is not the column. It is the result of a function applied to the column, which MySQL can only obtain by reading every row and calling DATE() on each one. The same rule shows up in the ORDER BY documentation, where ORDER BY ABS(key) is listed as a case where the index cannot resolve the sort.

What I want on record is why that DATE() was there in the first place, because it was not stupidity. issued_at is a DATETIME. Write BETWEEN '2014-11-01' AND '2014-11-30' against a DATETIME and you silently lose every invoice issued after midnight on the 30th, because the end of the range is compared as 2014-11-30 00:00:00. Wrapping the column in DATE() fixes the wrong answer and creates the slow one. The fix that does both is a half open range:

WHERE i.issued_at >= '2014-11-01' AND i.issued_at < '2014-12-01'

With that rewrite alone, the single column index finally got used: type became range, key_len 8, and rows dropped to 61,232. Query time fell from 41 seconds to 6.2. Better, and still embarrassing, because 61,232 rows were being read to produce 63.

Column order decides everything

The gap between 61,232 and the roughly 8,000 rows that actually matter is branch_id and status, which were still being tested row by row after the index had done its part. A composite index fixes that, and the order of its columns is the entire design decision.

The rule is the leftmost prefix. MySQL can use a multiple column index for queries that test all the columns in the index, or just the first column, the first two, and so on, and it cannot use the index for lookups if the columns do not form a leftmost prefix. A range on a column stops the index there: everything after the range column is no longer in useful order for lookups. So equality predicates go first, and the range goes last.

CREATE INDEX idx_invoice_report
    ON invoice (branch_id, status, issued_at, customer_id, total);
+----+-------------+-------+--------+-----------------------------------------------------+--------------------+---------+-------------------+------+-----------------------------------------------------------+
| id | select_type | table | type   | possible_keys                                       | key                | key_len | ref               | rows | Extra                                                     |
+----+-------------+-------+--------+-----------------------------------------------------+--------------------+---------+-------------------+------+-----------------------------------------------------------+
|  1 | SIMPLE      | i     | range  | idx_status,idx_invoice_issued_at,idx_invoice_report | idx_invoice_report |      62 | NULL              | 8412 | Using where; Using index; Using temporary; Using filesort |
|  1 | SIMPLE      | c     | eq_ref | PRIMARY                                             | PRIMARY            |       4 | erp.i.customer_id |    1 |                                                           |
+----+-------------+-------+--------+-----------------------------------------------------+--------------------+---------+-------------------+------+-----------------------------------------------------------+

8,412 rows instead of 1,921,664, and 0.42 seconds instead of 41. The key_len of 62 is worth reading slowly, because it is how you check that MySQL used the part of the index you think it used. It is the first three columns and no more: 4 bytes for branch_id (INT NOT NULL), 50 for status (VARCHAR(16) NOT NULL in utf8, so 16 characters at 3 bytes plus 2 length bytes), and 8 for issued_at (a DATETIME on 5.5). Had any of them been nullable, each would have cost one byte more. If I had written the columns in the order I first wanted, (issued_at, branch_id, status), the range on issued_at would have come first and the other two would have been decoration.

Covering the columns the report reads

The last two columns in that index, customer_id and total, are not filtered on at all. They are there so the index contains every column the query touches, which is what Using index in the Extra column means: the information is retrieved using only the index tree, without an additional seek to read the actual row. For 8,412 rows that is 8,412 random reads saved. It is also why the index is wide, and wide indexes are not free.

The detail listing under the summary, the one that prints each invoice, got a second benefit for free. It reads the same three filter columns and ends with ORDER BY i.issued_at DESC. Because branch_id and status are constants in the WHERE clause, the rows come out of the index already ordered by issued_at, and the manual says an index can satisfy an ORDER BY when all the unused portions of the index and all the extra ordered columns are constants. Using filesort disappeared from that plan entirely. It is still in the summary plan, and it always will be, because you cannot index a SUM().

What it cost, and what is still slow

Building the index took 6 minutes 40 seconds and I ran it at one in the morning, because on 5.5 that is not an online operation. The manual is exact: while an InnoDB secondary index is being created or dropped, the table is locked in shared mode, writes are blocked and reads still work. Anyone posting an invoice during those seven minutes would have sat there watching a spinner. The tablespace grew by 88 MB, and every insert into invoice now maintains one more index, which I have not been able to measure as anything above noise on our write volume.

The report page went from 41 seconds to 1.1. I kept idx_invoice_issued_at, the index from my wrong first attempt, because two other reports run date ranges across all branches and it serves them, but I want to be clear that I kept it after checking, not because I was attached to it.

Still wrong: five other queries in the reporting module wrap issued_at in DATE(), and I have only fixed the one that hurt. The month-end aging report has a correlated subquery that EXPLAIN shows as DEPENDENT SUBQUERY, which is next. And MySQL 5.6 adds index condition pushdown, which pushes parts of the WHERE clause down into the index scan for secondary indexes on InnoDB, and would help exactly the shape of query I spent four days on. We are not upgrading this quarter. Until then the rule is the one I wrote on the whiteboard that Tuesday: equality columns first, range column last, and never wrap an indexed column in a function.

Sources