When order of appearance of indexes matters in MySQL

Sometimes MySQL surprises you in ways you would have never imagined.

Would you think that the order in which the indexes appear in a table matters?
It does. Mind you, not the order of the columns - the order of the indexes.
MySQL optimizer can, in specific circumstances, take different paths, sometimes with nefarious effects.


Please consider the following table:

CREATE TABLE `mypartitionedtable ` (
  `HASH_ID` char(64) NOT NULL,
  `RAW_DATA` mediumblob NOT NULL,
  `EXPIRE_DATE` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  KEY `EXPIRE_DATE_IX` (`EXPIRE_DATE`),
  KEY `HASH_ID_IX` (`HASH_ID`)
) ENGINE=TokuDB DEFAULT CHARSET=latin1 ROW_FORMAT=TOKUDB_UNCOMPRESSED
/*!50100 PARTITION BY RANGE (UNIX_TIMESTAMP(EXPIRE_DATE))
(PARTITION p2005 VALUES LESS THAN (1487847600) ENGINE = TokuDB,
 PARTITION p2006 VALUES LESS THAN (1487851200) ENGINE = TokuDB,
 PARTITION p2007 VALUES LESS THAN (1487854800) ENGINE = TokuDB,
 PARTITION p2008 VALUES LESS THAN (1487858400) ENGINE = TokuDB,
[ ... ]


This is a table where we store key-value data for a cache. The table is partitioned by range on the cache expire date, so we can actually apply retention to the cache data.

Now, consider the following DML:

DELETE FROM mypartitionedtable WHERE HASH_ID = 'somehash' AND EXPIRE_DATE > NOW() ;

One would think that the plan for the query above is optimal: it goes by HASH_ID_IX index and also prunes partitions, by only looking at partitions with non-expired data.

In reality, it depends. 

Statistics for partitioned tables in MySQL are only computed on the largest partition. 

This works well most of the times, *except* when the largest partition becomes one of the expired ones.

Let's see this in detail...

We have several partitions, each partition contains a different day worth of data, based on values of the EXPIRE_DATE column. For the purpose of this post, let's assume partition p654 contains yesterday's data, and partition p666 contains data with an expire date which falls tomorrow. 

If we explain a query for a partition that contains valid cache data, i.e. a partition that has all rows with EXPIRE_DATE in the future, everything looks good: you can see that the cost for a search by HASH_ID is much less than the cost for a search by EXPIRE_DATE, as highlighted by the value of the "rows" column:

mysql>EXPLAIN SELECT COUNT(*) FROM BIG_STORAGE_INNO PARTITION(p666) WHERE EXPIRE_DATE > NOW();

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

| id | select_type | table            | type  | possible_keys  | key            | key_len | ref  | rows   | Extra                    |

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

|  1 | SIMPLE      | BIG_STORAGE_INNO | range | EXPIRE_DATE_IX | EXPIRE_DATE_IX | 5       | NULL | 291978 | Using where; Using index |

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

1 row in set (0.00 sec)

mysql>EXPLAIN SELECT COUNT(*) FROM BIG_STORAGE_INNO PARTITION(p666) WHERE HASH_ID = 'any hash value';

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

| id | select_type | table            | type | possible_keys | key     | key_len | ref   | rows | Extra                    |

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

|  1 | SIMPLE      | BIG_STORAGE_INNO | ref  | HASH_ID       | HASH_ID | 64      | const |    1 | Using where; Using index |

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

1 row in set (0.01 sec)

But what happens if we explain the same query for a partition which has all rows with an EXPIRE_DATE in the past?

mysql>EXPLAIN SELECT COUNT(*) FROM BIG_STORAGE_INNO PARTITION(p654) WHERE HASH_ID = 'any hash value';

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

| id | select_type | table            | type | possible_keys | key     | key_len | ref   | rows | Extra                    |

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

|  1 | SIMPLE      | BIG_STORAGE_INNO | ref  | HASH_ID       | HASH_ID | 64      | const |    1 | Using where; Using index |

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

1 row in set (0.00 sec)

mysql>EXPLAIN SELECT COUNT(*) FROM BIG_STORAGE_INNO PARTITION(p654) WHERE EXPIRE_DATE > NOW();

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

| id | select_type | table            | type  | possible_keys  | key            | key_len | ref  | rows | Extra                    |

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

|  1 | SIMPLE      | BIG_STORAGE_INNO | range | EXPIRE_DATE_IX | EXPIRE_DATE_IX | 5       | NULL |    1 | Using where; Using index |

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

1 row in set (0.01 sec)

Whoa, cost is the same for both queries now!

This has a very bad effect, as the optimizer will choose to use EXPIRE_DATE to select our rows and disregard HASH_ID completely.  And it will do this for all partitions, not just this one (where the plan actually would be ok).

Our DELETE above becomes now a locking scan of all partitions having EXPIRE_DATE > NOW(), this means (in our case) almost the entire table.

Ouch!!

This is in my opinion a bug - the fact that the optimizer only looks at the largest partition is ... sub-optimal, if you ask me. But in this case, the optimizer should also evaluate that EXPIRE_DATE is a partitioning key and choose the other index for the query, which would be correct.

Now for the fun part of this post.  

I was puzzled about what was causing the optimizer to pick one index and not the other, considering that they had identical cost. Unfortunately, explain wasn't telling me anything useful, so I decided to instrument some debugging to find out.

Debugging the MySQL server actually involves either recompiling from source with debugging option enabled, or (for lazy DBAs like myself) installing the debug package from your vendor of choice.

I was glad to find out that the stock Oracle distribution (Community edition) already includes the debugging binary of the server, called mysqld-debug. So I stopped the server, replaced mysqld with mysqld-debug, and restarted.

This was not enough, however, to have any debug output.  A quick look at the manual and I found that there is a variable that needs instrumented, called simply debug. More information about debugging MySQL is here, however all it's needed is to set this global variable as follows:

mysql>set global debug='d:L:F:O';

This will cause debugging output to go to the MySQL error log. It will print debugging output prefixed by source code file and line , useful if you want to look at source code to understand what's going on. 

So I ran the explain for the DELETE on the partition with yesterday data, and here is what I got (uninteresting debugging output removed for clarity):

 opt_range.cc:   264: get_key_scans_params: opt: range_scan_alternatives: starting struct
  opt_range.cc:   264: get_key_scans_params: opt: (null): starting struct
  opt_range.cc:   299: get_key_scans_params: opt: index: "EXPIRE_DATE_IX"
  opt_range.cc:  9541: check_quick_select: exit: Records: 4
  opt_range.cc:   264: get_key_scans_params: opt: ranges: starting struct
  opt_range.cc:   299: get_key_scans_params: opt: (null): "2017-02-22 17:28:51 < EXPIRE_DATE"
  opt_range.cc:   279: get_key_scans_params: opt: ranges: ending struct
  opt_range.cc:   313: get_key_scans_params: opt: index_dives_for_eq_ranges: 1
  opt_range.cc:   313: get_key_scans_params: opt: rowid_ordered: 0
  opt_range.cc:   313: get_key_scans_params: opt: using_mrr: 0
  opt_range.cc:   313: get_key_scans_params: opt: index_only: 0
  opt_range.cc:   336: get_key_scans_params: opt: rows: 4
  opt_range.cc:   347: get_key_scans_params: opt: cost: 5.81
  opt_range.cc:   313: get_key_scans_params: opt: chosen: 1
  opt_range.cc:   279: get_key_scans_params: opt: (null): ending struct
  opt_range.cc:   264: get_key_scans_params: opt: (null): starting struct
  opt_range.cc:   299: get_key_scans_params: opt: index: "HASH_ID"
  opt_range.cc:  9541: check_quick_select: exit: Records: 4
  opt_range.cc:   264: get_key_scans_params: opt: ranges: starting struct
  opt_range.cc:   299: get_key_scans_params: opt: (null): "925445622fe6c9da0a432b3e686b807557c215f04233b59a94b7eff1cb6ef3d9 <= HASH_ID <= 925445622fe6c9da0a432b3e686b807557c215f04233b59a94b7eff1cb6ef3d9"
  opt_range.cc:   279: get_key_scans_params: opt: ranges: ending struct
  opt_range.cc:   313: get_key_scans_params: opt: index_dives_for_eq_ranges: 1
  opt_range.cc:   313: get_key_scans_params: opt: rowid_ordered: 1
  opt_range.cc:   313: get_key_scans_params: opt: using_mrr: 0
  opt_range.cc:   313: get_key_scans_params: opt: index_only: 0
  opt_range.cc:   336: get_key_scans_params: opt: rows: 4
  opt_range.cc:   347: get_key_scans_params: opt: cost: 5.81
  opt_range.cc:   313: get_key_scans_params: opt: chosen: 0
  opt_range.cc:   299: get_key_scans_params: opt: cause: "cost"
  opt_range.cc:   279: get_key_scans_params: opt: (null): ending struct
  opt_range.cc: 13830: print_sel_tree: info: SEL_TREE: 0x7f58c00b1fd8 (ROR scans)  scans: HASH_ID
  opt_range.cc:  5676: get_key_scans_params: info: Returning range plan for key EXPIRE_DATE_IX, cost 5.81, records 4

By looking at the output above, it was confirmed that the optimizer was giving the two indexes the same exact cost: 5.81.  The index on EXPIRE_DATE was selected (chosen: 1) and the other one discarded (cause: "cost").

To me, this looked quite like an arbitrary decision to pick the first index of the set, all costs being equal. 

Makes sense? 

Well, it does, if cost is really identical, but in my case, I think the optimizer should have considered that one of the two indexes is a partitioning key, and pick the other. 

I said this was an arbitrary decision. 

But, the same decision could have been: pick the *last* index of the set, instead of the first. 

Hey, let's patch the source code, I thought. But then an idea came to my mind.  What if the order of appearance of the indexes in the table was reversed? After all, the code is simply scanning all available indexes, one at a time, evaluating them and assigning each of them a cost.

I quickly created another identical table, but with the order of the two indexes reversed:

CREATE TABLE `BIG_STORAGE_INNO` (

  `HASH_ID` char(64) NOT NULL,

  `SERIALIZATION_TYPE` enum('JAVA','PROTOSTUFF') NOT NULL,

  `COMPRESSION_TYPE` enum('DEFLATE','LZ4','NONE','GZIP') NOT NULL,

  `RAW_DATA` mediumblob NOT NULL,

  `LAST_UPDATE` datetime NOT NULL,

  `EXPIRE_DATE` datetime NOT NULL,

  KEY `HASH_ID_IX` (`HASH_ID`),

  KEY `EXPIRE_DATE_IX` (`EXPIRE_DATE`)

) ENGINE=InnoDB DEFAULT CHARSET=latin1

/*!50100 PARTITION BY RANGE (TO_DAYS(EXPIRE_DATE))

(PARTITION p654 VALUES LESS THAN (736741) ENGINE = InnoDB,

 PARTITION p655 VALUES LESS THAN (736742) ENGINE = InnoDB,

 PARTITION p656 VALUES LESS THAN (736743) ENGINE = InnoDB,

 PARTITION p657 VALUES LESS THAN (736744) ENGINE = InnoDB,

 PARTITION p658 VALUES LESS THAN (736745) ENGINE = InnoDB,

 [ .... ]

You can see that the order of the columns is the same as before, but the order of the two indexes is reversed - now HASH_ID_IX comes first. 

Guess what happens now in the optimizer?

opt_range.cc:   264: get_key_scans_params: opt: range_scan_alternatives: starting struct
  opt_range.cc:   264: get_key_scans_params: opt: (null): starting struct
  opt_range.cc:   299: get_key_scans_params: opt: index: "HASH_ID_IX"
  opt_range.cc:  9541: check_quick_select: exit: Records: 4
  opt_range.cc:   264: get_key_scans_params: opt: ranges: starting struct
  opt_range.cc:   299: get_key_scans_params: opt: (null): "925445622fe6c9da0a432b3e686b807557c215f04233b59a94b7eff1cb6ef3d9 <= HASH_ID <= 925445622fe6c9da0a432b3e686b807557c215f04233b59a94b7eff1cb6ef3d9"
  opt_range.cc:   279: get_key_scans_params: opt: ranges: ending struct
  opt_range.cc:   313: get_key_scans_params: opt: index_dives_for_eq_ranges: 1
  opt_range.cc:   313: get_key_scans_params: opt: rowid_ordered: 1
  opt_range.cc:   313: get_key_scans_params: opt: using_mrr: 0
  opt_range.cc:   313: get_key_scans_params: opt: index_only: 0
  opt_range.cc:   336: get_key_scans_params: opt: rows: 4
  opt_range.cc:   347: get_key_scans_params: opt: cost: 5.81
  opt_range.cc:   313: get_key_scans_params: opt: chosen: 1
  opt_range.cc:   279: get_key_scans_params: opt: (null): ending struct
  opt_range.cc:   264: get_key_scans_params: opt: (null): starting struct
  opt_range.cc:   299: get_key_scans_params: opt: index: "EXPIRE_DATE_IX"
  opt_range.cc:  9541: check_quick_select: exit: Records: 4
  opt_range.cc:   264: get_key_scans_params: opt: ranges: starting struct
  opt_range.cc:   299: get_key_scans_params: opt: (null): "2017-02-22 18:20:05 < EXPIRE_DATE"
  opt_range.cc:   279: get_key_scans_params: opt: ranges: ending struct
  opt_range.cc:   313: get_key_scans_params: opt: index_dives_for_eq_ranges: 1
  opt_range.cc:   313: get_key_scans_params: opt: rowid_ordered: 0
  opt_range.cc:   313: get_key_scans_params: opt: using_mrr: 0
  opt_range.cc:   313: get_key_scans_params: opt: index_only: 0
  opt_range.cc:   336: get_key_scans_params: opt: rows: 4
  opt_range.cc:   347: get_key_scans_params: opt: cost: 5.81
  opt_range.cc:   313: get_key_scans_params: opt: chosen: 0
  opt_range.cc:   299: get_key_scans_params: opt: cause: "cost"
  opt_range.cc:   279: get_key_scans_params: opt: (null): ending struct
  opt_range.cc: 13830: print_sel_tree: info: SEL_TREE: 0x7f7da4095838 (ROR scans)  scans: HASH_ID_IX
  opt_range.cc:  5676: get_key_scans_params: info: Returning range plan for key HASH_ID_IX, cost 5.81, records 4

Bingo!!  The right index comes first now, and is chosen in every situation.

My problem is solved - well, I call this a workaround, although an interesting one.

I have raised a bug on the subject, I really believe that in this situation, the fact that one of the two identically expensive indexes is a partitioning key should be taken into account.

For sure this has been an amusing troubleshooting... and an interesting finding!

ADDENDUM:

I have just discovered that the order of appearance of indexes also matters (a lot) when using row based replication and tables without a primary key!

 The sql thread will use the first index in order of appearance to scan the table if it needs to search rows for an update .... this may result in very long time spent searching for rows if the first index in the table is not very selective. You can spot that because the slave thread will spend lot of time in  Update_rows_log_event::find_row state for each update statement on the table without the PK. 

The fix is to make sure a very selective index appears first in the table. This may be a life saver (it was in my case!)

Hope this helps!

Rick

If enforcing data retention via DROP PARTITION, better watch your auto_increment counter

One of the main tasks that any DBA has to deal with is certainly data retention. Especially when your developers like to store logging and tracking information inside the database. This is not something that I would recommend (don't try it at home!) but when you're late to the party (read: someone had taken this path before you joined) , then you'll have to live with it.

Data retention in MySQL is usually applied by partitioning the table by RANGE on a selected column, usually containing the row creation timestamp. New partitions are created in advance for the coming days or weeks or months, and a script is used that will run nightly and drop partitions that are older than a set retention.

There are many tools that can be used to automate data retention; I have chosen the excellent pdb-parted, a nice and cozy perl script that you can find in the PalominoDB repository on GitHub (since PalominoDB is no longer in existence, I have forked the repository under my own account, you can also get the script here).

It goes without saying that when I first joined, although there were many tables already containing millions of rows of logging, statistical and tracking data, there were no pruners in effect, i.e. no retention at all was applied. Over the next weeks and months I managed to get the required information from the various dev teams and started pruning the bigger tables.  After a couple of months of strict diet, I had recovered about 250 GB of space out of our main cluster, or about 30% of total dataset size at that time. Not bad!  Backup and restore times improved, and also their footprint was much smaller.

Over the next several months the company kept growing very fast. A DWH Team was set up and they started ingesting data from MySQL inside their own systems (Vertica based). Some of the data that was ingested was coming from these pruned tables.

Everything went well for some time, then I received a visit from one of the DWH guys with a strange issue: they were seeing duplicate keys in the data ingested from one of the partitioned tables.  I knew that, in theory, this should not be possible, as each and every table of that type has an auto increment primary key, and we had no reports of duplicate keys in production when data was first inserted.

At first I tried to blame the ETLs that they use to import data from MySQL to Vertica, but soon I realised that the table that they were having the issue with had a notable difference:  it was really small in size, only few hundreds rows, while all other tables contained hundreds of millions.  So I asked them for the MAX value of the auto increment key they had in their systems, and to my surprise, it was higher than the MAX value we had in MySQL!!! D'oh.

After some investigation it turned out that this particular table was only used for debugging, therefore the application  was not writing to it  unless the debug mode was activated. Usually, debug was only turned on for small amount of time (e.g. hours) and then turned off again, and the saved data was used for troubleshooting.

Anyways, it was clear that somehow, the auto_increment in this table was getting reset at some point; it was the only possibility for having an higher value in DWH than what we had in MySQL, as DWH was basically ingesting our rows directly, without any modification whatsoever.

It was easy enough for me to point the finger here, as the only statement that was issued against this table, apart from INSERT, was.... DROP PARTITION.

You will object that DROP PARTITION does not reset the auto_increment counter of a table. Of course I agree, but there was no other possibility here, so it had to be some kind of bug.

It was easy enough to reproduce the behaviour and to confirm that, if the partition you are dropping leaves no other rows in the table, the auto_increment counter is, in fact, reset to 1. You can find the steps in the bug I have submitted to Oracle (please see below).

In my opinion, the behaviour of auto_increment in this situation is not consistent:

• TRUNCATE TABLE (DDL) empties the table, counter is reset => OK
• DELETE * FROM TABLE (DML) empties the table, counter is NOT reset => OK
• DROP PARTITION (DDL) does NOT empty the table, merely drops some data - counter is reset or not depending on content of other partitions  => WEIRD

I really feel that the auto_increment should be left alone when DROP PARTITION is issued, regardless what the content of the other partitions is.

I invite you to check the bug content for some discussion that I had with the Oracle bugs team, where they tried to convince me that this behaviour was correct at first, then acknowledged, but there was not much activity after that.