[MDEV-23228] Optimizer chooses bad Execution Plan in wordpress query Created: 2020-07-20 Updated: 2023-04-27 |
|
| Status: | Confirmed |
| Project: | MariaDB Server |
| Component/s: | Optimizer |
| Affects Version/s: | 10.3, 10.4, 10.5 |
| Fix Version/s: | 10.4, 10.5 |
| Type: | Bug | Priority: | Major |
| Reporter: | Oli Sennhauser | Assignee: | Sergei Petrunia |
| Resolution: | Unresolved | Votes: | 1 |
| Labels: | in-to-subquery, performance, regression | ||
| Attachments: |
|
| Description |
|
Optimizer chooses bad strategy for some word press queries on table wp_postmeta:
Execution time about: 100 - 110 ms.
Execution time: About 150 ms (50% worse). We did not find any way to force the optimizer to choose the older execution plan with optimizer_switches: set session optimizer_switch='materialization=off,semijoin=off'; https://mariadb.org/wp-content/uploads/2018/07/state-of-mariadb-optimizer-r08.pdf Further a Execution Plan of a competitive product did slightly better:
Execution time: 80 ms (100% improvement to the previous). We were not able to enforce this better Execution plan with optimizer_switches either: set session optimizer_switch='mrr=on,mrr_sort_keys=on'; (psergey: edited to make more readable) |
| Comments |
| Comment by Varun Gupta (Inactive) [ 2020-07-22 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
oli you can disable this optimization on 10.3 by setting in_predicate_conversion_threshold to 0. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-22 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
OK. This solves part of the problem: in_predicate_conversion_threshold=1200 or 0 produces the old pre 10.3 QEP. But still slower than competing product. I try to play a bit more with it if I can enforce mrr... | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-22 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
oli, we were also thinking about the cause of the slowdown (conversion of IN predicate into a subquery as such should not cause a slowdown). Could you try the query without the ORDER BY clause on | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-22 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
This should do it :
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-23 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
SELECT @@version;
-----------------
----------------- SELECT @@optimizer_switch\G
-----
-----
----- | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-23 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
SELECT @@version;
-----------------
----------------- SELECT @@optimizer_switch\G
SELECT @@in_predicate_conversion_threshold;
-------------------------------------
------------------------------------- -----
-----
----- | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-23 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
SET SESSION optimizer_switch='mrr=on'; With ORDER BY:
-----
----- Without ORDER BY:
-----
----- I cannot see any MRR optimization. MariaDB docu mentions: https://mariadb.com/kb/en/multi-range-read-optimization/
We have: WHERE id IN (1100 values). Possibly MRR is not considered in this case? I can ask customer if I can send you the data if it helps? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-24 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Analyzing of the provided data: So, if one removes the ORDER BY,
roughly the same. This seems to prove the theory that:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-24 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Another thing to check: what is the "Using index condition" for table wp_postmeta?
which is a bit odd as wp_postmeta.post_id was defined as
and normally the optimizer is able to detect that in such cases the returned row satisfies the WHERE condition.. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-24 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
The query profile supports your idea:
By the way: I got OK from customer to upload you the data if needed? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-25 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Sorry, I was not clear enough. I intended to say this:
Then, MRR is used (The EXPLAIN shows it as "Rowid-ordered scan"):
Without in_predicate_conversion_threshold=0, one can get MRR to be used by enabling batched key access:
...But looking at the numbers of rows to be read, I doubt that this will reliably help. oli, can you try with "set optimizer_switch='mrr=off'" on MySQL 8? Does it have any effect on the query execution time? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-25 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
If it is not too bothersome - let's give it a try, please upload. (Because I haven't been able to reproduce with the test data I have generated). | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-25 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Tried to reproduce: mdev23228-fill-tables.sql The query: mdev23228-q-timings.sql The results (all values are time in Microseconds):
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-25 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
So, for me Query time distribution is interesting. MySQL is highly predictable while MariaDB has "unlucky runs" which are much slower than normal. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-27 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Dump, Create Table and Query: cat xa? > wp_postmeta.tar.gz | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-27 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Oli Sennhauser [ 2020-07-27 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
8.0.20-commercial Enterprise Server
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-29 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
oli, thanks for the dataset. Played with it on my side. (The query times are microseconds, each query is tried 100 times) Results
Two angles:
| ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Sergei Petrunia [ 2020-07-29 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Roel, could you try on your side (the details are in the email) | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Roel Van de Paar [ 2020-07-30 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Original posted issue confirmed. I did this on a large Google cloud instance which was otherwise idle.
Note the rather large increase for 10.3, which indeed seems like a performance regression. Subsequent runs of the same query still vary though less; caching of any sort likely kicked in, especially as run times are shorter. The results in that case were 0.11 seconds (10.2.33) and 0.170 seconds (10.3.24). Still a significant difference. This result is repeatable (0.11/0.166 on next run), and is deemed non-sporadic. I next tested 10.5.5 (again on a freshly created instance) and the result there was:
A significantly worse result on the first query. Subsequent runs gave 0.186 sec and 0.179 sec respectively, which is close to 10.3 performance. It thus seems like there is a regression starting with 10.3 only. I next test 10.4 to see what the outcome was there. For the first query there was;
And subsequent queries gave 0.170 sec and 0.170 sec again on the third run. I thus conclude that the performance regression started in 10.3 and continues to exist today. Note that the use of the CLI may mean that the output is slow (has regressed) versus the actual query being slow. To analyze this further, I re-enabled EXPLAIN to see if there was a difference in query execution plan on my side also. I also re-initalized the server completely to have a fresh environment and avoid any caching from affecting things. Results:
In summary; the changed query execution plan seems to lead to a significant performance regression from 10.3 onwards. Looking at the number of rows, perhaps the issue is that in 10.3 onwards, there are 1128 rows x? 1128 = 1272384? rows accessed, versus 25301 rows in the first one? Just an idea. Another reason may be the "using temporary"? I also checked 10.4 and 10.5 query execution plans, and they almost completely match, though for the number of rows (marked by 'REF' in the last EXPLAIN about above) there are 2 rows instead of 1 row for 10.4.14, and 3 rows instead of 1 row for 10.5.5 which seems very odd. Note also that in the original issue posted it's 4 I've updated the bug tags. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Roel Van de Paar [ 2020-07-30 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
oli Please note that the uploaded data is public and available to anyone even without logging in. Just want to make sure you're clear on that. Thanks. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Christoph Zysik [ 2021-03-07 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
I wonder if this is related, possible_keys -> yes Only solution is to use force key to get the resource usage down to a sane level again. Used Query is something like |