19

I am diagnosing an intermittent slow query, and have found a strange behaviour in MySQL I cannot explain. It's choosing a different, non-optimal key strategy for one specific case, only when doing a LIMIT 1.

Table (some unreferenced data columns removed for brevity)

CREATE TABLE `ch_log` (
    `cl_id` BIGINT(20) NOT NULL AUTO_INCREMENT,
    `cl_unit_id` INT(11) NOT NULL DEFAULT '0',
    `cl_date` DATETIME NOT NULL DEFAULT '0000-00-00 00:00:00',
    `cl_type` CHAR(1) NOT NULL DEFAULT '',
    `cl_data` TEXT NOT NULL,
    `cl_event` VARCHAR(255) NULL DEFAULT NULL,
    `cl_timestamp` TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
    `cl_record_status` CHAR(1) NOT NULL DEFAULT 'a',
    PRIMARY KEY (`cl_id`),
    INDEX `cl_type` (`cl_type`),
    INDEX `cl_date` (`cl_date`),
    INDEX `cl_event` (`cl_event`),
    INDEX `cl_unit_id` (`cl_unit_id`),
    INDEX `log_type_unit_id` (`cl_unit_id`, `cl_type`),
    INDEX `unique_user` (`cl_user_number`, `cl_unit_id`)
)
ENGINE=InnoDB
AUTO_INCREMENT=419582094;

This is the query, which only runs slow for one specific cl_unit_id:

EXPLAIN
SELECT *
FROM `ch_log`
WHERE `ch_log_type` ='I' and ch_log_event = 'G'  
AND cl_unit_id=1234
ORDER BY cl_date DESC 
LIMIT 1;
id|select_type|table |type |possible_keys                               |key    |key_len|ref|rows|Extra
1 |SIMPLE     |ch_log|index|cl_type,cl_event,cl_unit_id,log_type_unit_id|cl_date|8      |\N |5295|Using where

For all other values of cl_unit_id it uses the log_type_unit_id key which is much faster.

id|select_type|table |type|possible_keys                                           |key             |key_len|ref        |rows|Extra
1 |SIMPLE     |ch_log|ref |ch_log_type,ch_log_event,ch_log_unit_id,log_type_unit_id|log_type_unit_id|5      |const,const|3804|Using where; Using filesort
  • All queries take about 0.01 seconds.
  • The "slow unit" query takes 10-15 minutes!

I can't see anything strange about the data for this 'unit':

  • Unit 1234 only has 6 records of type I and event G.
  • Other units have many more.
  • Unit 1234 only has 32,000 logs in total which is typical.
  • the data itself is normal, no bigger or older.
  • There are around 3,000 "units" in the database, which represent devices logging stuff. The cl_unit_id is their unique PK (although no constraint).

General info

  • There are 30m records in total, around 12GB
  • mysql 5.1.69-log
  • Centos 64bit
  • The data is gradually changing (30m = 3months of logs) but I don't know if this has happened before

Things I've tried, and can "solve" the problem with:

  1. Removing the LIMIT 1 - the query runs in milliseconds and returns the data.

  2. Changing to LIMIT 2 or other combinations e.g. 2,3 - runs in milliseconds.

  3. Adding a index hint - solves it:

    FROM `ch_log` USE INDEX (log_type_unit_id)
    

    but... I don't want to hard-code this into the application.

  4. Adding a second order by on the primary key also "solves" it:

    ORDER BY cl_id, cl_date DESC 
    

    giving explain:

    id|select_type|table |type|possible_keys                                           |key             |key_len|ref        |rows|Extra
    1 |SIMPLE     |ch_log|ref |ch_log_type,ch_log_event,ch_log_unit_id,log_type_unit_id|log_type_unit_id|5      |const,const|6870|Using where
    

    which is slightly different to the type hinted one, with more records examined (6,000) but still runs in 10's of milliseconds.

Again I could do this, but I don't like using side-effects I don't understand.

So I think my main question are:

a) why does it only happen for LIMIT 1?

b) how can the data itself affect the key-strategy so much? And what aspect of the data, seeing as the quantity and spread in the indexes seems typical.

scipilot
  • 6,681
  • 1
  • 46
  • 65
  • This is a great question. Can you post this to http://dba.stackexchange.com/ also? – zedfoxus Jul 15 '15 at 03:04
  • I think I know what's going on. But first, please clarify `For all other unit_id it uses the log_type_unit_id key which is much faster.` What do you mean 'all other unit_id' ? Could you post the matching query, just to make sure? – Sebas Jul 15 '15 at 03:05
  • The query is generated by a server so unit_id=1234 will be anything between 1-3000, depending on the "unit" or device being queried. thanks – scipilot Jul 15 '15 at 03:06
  • @zedfoxus of course! but is it OK to cross-post? – scipilot Jul 15 '15 at 03:07
  • how often do you order by cl_date by itself? this seems pretty index happy (liberal) – Drew Jul 15 '15 at 03:10
  • why do you have *both* of these: INDEX `cl_unit_id` (`cl_unit_id`), INDEX `log_type_unit_id` (`cl_unit_id`, `cl_type`) .... why not just have the 2nd one – Drew Jul 15 '15 at 03:18
  • @DrewPierce yes it's a 10-year old app, and previously people have added keys relatively indiscriminately. It's now hard to change as most changes take hours of table lock. But to answer your question, I'm not sure, I'd have to scan a lot of code... Also cl_date has a very high cardinality, probably 80% of the number of rows. – scipilot Jul 15 '15 at 03:20
  • fair enough on cardinality, but are there queries that go after the data in that table that way, or might it be shotgun index legacy from prior devs. – Drew Jul 15 '15 at 03:23
  • 1
    so i would consider this (not knowing your query paths). ditch a truly unused index, and have a composite on (uid,date). easy for me to say. easy to also say analyze table and force index on that new composite. the order by is making it drop an egg regardless of limit 1 – Drew Jul 15 '15 at 03:26
  • 1
    Thanks @DrewPierce, yes I do plan to do a key clean-up job one day, but it's just so hard on a production database without messing around with swapping slaves. And it's hard to scan 100,000s of lines of legacy code for all the combinations of keys and queries. The last key change I did took 8 hours of downtime! – scipilot Jul 15 '15 at 03:41
  • @scipilot This post is a good candidate for cross-posting. It is likely to interest more folks from dba SE community and it has already interested SO community – zedfoxus Jul 15 '15 at 15:44
  • It's not what you asked, so I will merely comment: This will probably avoid the slowness for all cases: `INDEX(cl_unit_id, ch_log_type, ch_log_event, cl_date)`. (`cl_date` must be last; the others can be in any order.) – Rick James Jul 26 '15 at 04:50

1 Answers1

10

Mysql will pick an explain plan and use different indexes depending on what it thinks is statistically the best choice. For all your first questions, this is the answer:

  1. Removing the LIMIT 1 - the query runs in milliseconds and returns the data. and -> Yes, check it, the explain plan is good
  2. Changing to LIMIT 2 or other combinations e.g. 2,3 - runs in milliseconds. -> the same applies. The optimizer chooses a different index because suddenly, the expected block reads became twice as big as with LIMIT 1 (that's just one possibility)
  3. Adding a index hint solves it -> Of course, you force a good explain plan
  4. Adding a second order by on the primary key also "solves" it -> yes, because by coincidence, the result is a better explain plan

Now, that only answers half of the questions.

a) why does it only happen for LIMIT 1?

It actually happens not only because of LIMIT 1, but because of

  • Your data statistic repartition (orients the optimizer's decisions)
  • Your ORDER BY DESC clause. Try with ORDER BY ... ASC and you will probably see an improvement too.

This phenomenon is perfectly aknowledged. Please read on.

One of the accepted solutions (bottom down in the article) is to force the index the same way you did. Yes, sometimes, it is justified. Otherwise, this hint thing would have been totally wiped out long ago. Robots cannot be always perfect :-)

b) how can the data itself affect the key-strategy so much? And what aspect of the data, seeing as the quantity and spread in the indexes seems typical.

You said it, the spread is what usually fucks up. Not only the optimizer might just make a wrong decision with accurate statistics, but it could also be completely off just because the delta on the table is right below 1 / 16th of the total row count...

Sebas
  • 21,192
  • 9
  • 55
  • 109
  • Thanks! I did read the Percona article before posting, but didn't feel it explained why LIMIT 1 specifically caused this. However after reading the second article you linked to, I ran SHOW TABLE STATUS, and now the query runs in `/* Affected rows: 0 Found rows: 1 Warnings: 0 Duration for 1 query: 0.141 sec. */` – scipilot Jul 15 '15 at 03:36
  • So I feel I understand a little more about the key strategy now, and in this case LIMIT 1 was just the unlucky configuration which, due to old data in the status, was using the wrong strategy. So there's nothing specific about LIMIT 1, it could have been anywhere... So is it acceptable to run a show table status in a cron job every night? – scipilot Jul 15 '15 at 03:38
  • 2
    Run `ANALYZE` statements instead (which is what is triggered by the `show table` statement). But you should investigate if it is normal that the statistics were outdated at this point. It seems that you were unlucky all the way, as it should happen automatically after 1/16th of the content of your logs has changed – Sebas Jul 15 '15 at 03:41
  • You understood well the unlucky part of the whole thing. Even though in reality, luck has little to do with it, the chance of that scenario happening is indeed very small :-) – Sebas Jul 15 '15 at 03:42
  • Thanks @Sebas I will look into using ANALYZE and why I'd even need it. – scipilot Jul 15 '15 at 03:56
  • @scipilot Take note: Oracle database provides a way to save and use an explain plan in particular. It allows you to refresh statistics safely, while still knowing that the given plan currently in use is good for your queries. But Mysql does not have this system. It means if your statistics get refreshed (which just happened) after being stale for a long time, you might notice a sudden drop in performance in other queries. If queries drop perf. with proper statistics, it might mean they need optimization, but in production you don't really have time for it! – Sebas Jul 15 '15 at 04:03
  • @scipilot - 5.7 (and later 5.6 versions?) has re-worked the cases when an `ANALYZE` is done. The result is that it almost always has the best of both worlds -- correctly remembering the stats, plus not having to do `ANALYZE` in hopes of fixing bad stats. – Rick James Jul 26 '15 at 04:56
  • Thanks @RickJames that's interesting. I tend to stick to the O/S repo versions which are always so far behind! So I'll check up on the latest available. – scipilot Jul 27 '15 at 05:08
  • BTW this problem has happened in production twice more since posting this question. The "fix" works, but it's certainly not a rare event for us. We get about 300,000 new logs per day, we have 30m total, so 1/16th is about 5-6 days, and this is exactly what we're seeing. The server locks up every weekend! (and gets me out of bed) – scipilot Jul 27 '15 at 05:11
  • @scipilot then cron the heck out of that analyze job :D – Sebas Jul 27 '15 at 15:15
  • 5.6.6 innodb_stats_auto_recalc and Persistent stats makes ANALYZE much better. MariaDB-10.0 has histogram-based stats; that should be even better. – Rick James Jul 27 '15 at 17:39