1

This is the last update to this very LONG post.

Problem Summary:

In a database containing a field for datetime and a field for milliseconds (and indexes for both), MySQL picks an index of milliseconds when I specify a query containing datetime, and it chooses the datetime index when I query on milliseconds. This happens across 6 independently built systems that have never been interconnected.

My Solution:

So to sum up what I'm going with for a solution--I tried everything suggested here and nothing actually causes MySQl to consistently "Pick" the correct index, but it will obey a hint. It seems that MySQL just has an unfixable bug in index choice and all I can do is suggest what index to use manually, so I'll pass a hint in from Hibernate.

It's not even like it's an optimizer issue--It's choosing an index with the entirely wrong data type!

I'll leave the question open for a while and see if I get any better answers, if not I'll post "Just tell MySQL which index to use because index selection is broken" as an answer.

The original post (with edits, very long):

I have a strange problem with MySQL (v. 8.00.37 GPL version using InnoDB).

I have a "Log" database. It includes the fields:

"level" (varchar (225)),
"timestamp" (datetime)
"timestamp_in_millis" (bigint)

We have created two indexes for this table, they are:

(level, timestamp)
(level, timestamp_in_millis).

Although other fields can be selected, for the testing I've done I've reduced it to these three fields and these two indexes only.

So the basic problem is that when I issue:

select * from log where level='INFO' and timestamp > "2024-07-10 23:59:00

it takes a very long time to return.

After taking a day to evaluate it and learning a LOT more about MySQL and indexing in the process I found that "explain" for that line tells me it's choosing the index including the "timestamp_in_millis" key.

Funny thing is that the line:

"explain select * from log where level='info' and timestamp_in_millis > '17198355046'

(A number I pulled that should be about the same as the other date) it says it's using the index with the "timestamp" and getting the same bad performance.

if I FORCE INDEX to the correct index, it fixes both queries (although strangely it says type is "range" when I would expect "INDEX" since I'm using the exact same parameters as in the index). This isn't an option for long-term though since we are using hibernate and I'm not sure hibernate will pass that through for us.

The other thing that makes it work is replacing level = 'INFO' with level LIKE 'INFO'. It will then choose to use the correct index and come back in a reasonable time. I figured this out after reading that ICP will pass down equals but not like, however disabling ICP didn't help.

Also note:

  • This cross-index behavior is completely reliable on all 6 environments that exhibit it after dozens of EXPLAIN statements on each.
  • All of the mysql servers are independent--we don't back up from one and restore to another or anything like that.

This same problem is repeatable on all dev, test, staging and production servers except one (I can't find anything unique about the one that works!). That's a total of 7 servers I've been testing, 5 that exhibit this behavior repeatedly, 100% of the time.

Things I've tried:

  • rebuilding indexes on my dev server. This once fixed it but then it broke when I did it again
  • rebuilding indexes on our test server. No effect, but takes to long to do repeatedly.
  • ANALYZE TABLE
  • OPTIMIZE TABLE
  • dropping all indexes and rebuilding them
  • Disabling Index Condition Pushdown
  • Using "Like" instead of "=" which did cause it to use the correct index partially.

Any hints as to more things I could try or a reason this might be happening?

show indexes from log looks like this: Show Indexes

The other query showed a very skewed distribution with most days having just a few entries at most levels but INFO has ~20K/day. Since our searches are typically level=ERROR that should be a good index I think.

Another bit of insanity I just discovered: the selected index is changing based on what columns are to be returned.

"explain select * from log where timestamp_in_millis > 1719878355046"

incorrectly selects the timestamp (datetime) index, however

explain select timestamp_in_millis from log where timestamp_in_millis > 1719878355046

selects the correct (Int) index. As I've come to expect, the reverse is true as well, where "select * from log where timestamp..." chooses the timestamp_in_millis, "select timestamp from log where..." chooses the correct timestamp index.

Improve this question
8
  • Sorry, my office is not connected to the internet so I couldn't do much copy and paste. the explain for the "timestamp" query said: select_type=SIMPLE. type=ref, possible_keys="idx_level_timestampInMillis, idx_timestamp", key=idx_level_timestampInMillis, key_len=257, ref=const, rows=4270245, filtered=13.00, extra="Using where"
    – Bill K
    Commented Jul 31 at 19:34
  • your database as you need to show your problem, is not complex. So rebuild it and paste the plan or use dbfiddle.uk/3aMmxpPT
    – nbk
    Commented Jul 31 at 19:37
  • 1
    Perhaps you can start with not using reserved words for names. See this one for example.
    – mustaccio
    Commented Jul 31 at 20:19
  • Really good point on the reserved names! Might be really hard to prove given the size of the table, but I'll experiment with it.
    – Bill K
    Commented Jul 31 at 21:16
  • sinply hint to the correct index, you can for development reasons make as man index as you like and test them all. and remove all unneeded indexes afterwords
    – nbk
    Commented Aug 8 at 18:49

1 Answer 1

Reset to default
1

I just noted your EXPLAIN plan statement

explain select * from log where level='info' and timestamp_in_millis > '17198355046'

The query is asking to compare the timestamp_in_millis to a string, not a number

Suggestion: Please remove the quotes from the number so it looks like this

explain select * from log where level='info' and timestamp_in_millis > 17198355046

I was thinking about the key distribution along the dates for each level. Please run this

select level,dt,count(1) cnt
from (select level,date(`timestamp`) dt from log) A
group by info,dt;

This will give you an idea of how many dates there are for each level.

For an estimate on the key distribution, please run this:

show indexes from log;

You will see the cardinality of level and the cardinality of the combinations of values

Improve this answer
8
  • Thank you for your response. I updated the question with the results of those commands but I'm not quite sure how to interpret them. I did remove the quotes from the millis value but it didn't have an effect, it still chose the "timestamp" index instead of the "timestamp in millis" index.
    – Bill K
    Commented Aug 2 at 17:50
  • The cardinality of 5 on the level is what scares me (and the query optimizer). Try creating the following index : ALTER TABLE log ADD INDEX timestamp_in_millis_ndx (timestamp_in_millis);. Then go that EXPLAIN plan. SIDE NOTE QUESTION : How many days of data do you keep in the log and how often do you purge the log table ???
    – RolandoMySQLDBA
    Commented Aug 2 at 18:05
  • We keep 90 days in dev, test and staging, In prod we keep them for longer (Closer to a year). We just delete records older than a set age, we don't ever purge the table (Didn't know it was required or recommended). After adding the new index it still chose the one that didn't have the millis: '1', 'SIMPLE', 'log', NULL, 'ref', 'idx_level_timestampInMillis,idx_level_timestamp,timestamp_in_millis_ndx', 'idx_level_timestamp', '257', 'const', '919204', '50.00', 'Using where'
    – Bill K
    Commented Aug 2 at 19:20
  • When I simply query: explain select * from log where timestamp_in_millis > 1719878355046; it considers the timestamp_in_millis_ndx buty then doesn't seem to choose it: '1', 'SIMPLE', 'log', NULL, 'ALL', 'timestamp_in_millis_ndx', NULL, NULL, NULL, '1838566', '50.00', 'Using where'
    – Bill K
    Commented Aug 2 at 19:28
  • That may be due to the number of rows being scan. If more than 5% of the rows need to be scanned, Query Optimizer forgets the potential indexes and goes with a full table scan.
    – RolandoMySQLDBA
    Commented Aug 2 at 19:54

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.