Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Duplicate
-
10.4.17
-
debian
Description
We have two hosts serving on the same replication topology with same hardware.
pc2007: runs 10.4.15
pc2010: runs 10.4.17
Those two hosts do not receive read traffic. All the traffic comes thru replication and it is mostly REPLACE statements.
However they do receive DELETEs from time to time.
After upgrading to 10.4.17 we noticed pc2010 (and another host) started to lag often, and it sort of matched the times where the DELETE arrived.
Investigating we saw that the host running 10.4.17 was having a very strange pattern regarding handler_read_next compared to the host running 10.4.15
10.4.17: https://phab.wmfusercontent.org/file/data/442ozs4b36ctxwzqdse5/PHID-FILE-hp6qf2cv6je4zoks3fvn/Captura_de_pantalla_2020-11-23_a_las_12.25.47.png
10.4.15: https://phab.wmfusercontent.org/file/data/byag7m3a4z3v5r4pe7l3/PHID-FILE-gt6pten2ty6no3czi23j/Captura_de_pantalla_2020-11-23_a_las_12.26.06.png
Both hosts run the same global variables and a diff doesn't really show any difference:
https://phabricator.wikimedia.org/P13361
There is +innodb_max_purge_lag_wait which was introduced on 10.4.16, but I asked Marko at https://jira.mariadb.org/browse/MDEV-16952 and he kindly pointed out that it should have no difference.
However, digging into the DELETEs optimizers behaviour we can see there's a big difference between 10.4.15 and 10.4.17
These are the handlers differences:
10.4.17: https://phabricator.wikimedia.org/P13362
10.4.15: https://phabricator.wikimedia.org/P13363
We can see the big difference there with the scans:
10.4.17
| Handler_read_next | 15218 |
|
10.4.15:
| Handler_read_next | 0 |
|
Checking the optimizer we can see there's a big difference on rows and cost:
Optimizer trace for 10.4.17: https://phabricator.wikimedia.org/P13365
Optimizer trace for 10.4.15: https://phabricator.wikimedia.org/P13364
This difference is interesting:
10.4.17:
|
|
"rowid_ordered": true,
|
"using_mrr": false,
|
"index_only": false,
|
"rows": 100,
|
"cost": 65515,
|
"chosen": true
|
},
|
{
|
"index": "exptime",
|
"ranges": ["(NULL) < (exptime) < (2020-11-21 18:06:30)"],
|
"rowid_ordered": false,
|
"using_mrr": false,
|
"index_only": false,
|
"rows": 26088,
|
"cost": 33264,
|
"chosen": true
|
}
|
],
|
"analyzing_index_merge_union": []
|
},
|
"chosen_range_access_summary": {
|
"range_access_plan": {
|
"type": "range_scan",
|
"index": "exptime",
|
"rows": 26088,
|
"ranges": ["(NULL) < (exptime) < (2020-11-21 18:06:30)"]
|
},
|
"rows_for_plan": 26088,
|
"cost_for_plan": 33264,
|
"chosen": true
|
Vs the much lighter 10.4.15 plan
"rowid_ordered": true,
|
"using_mrr": false,
|
"index_only": false,
|
"rows": 100,
|
"cost": 120.13,
|
"chosen": true
|
},
|
{
|
"index": "exptime",
|
"ranges": ["(NULL) < (exptime) < (2020-11-21 18:06:30)"],
|
"rowid_ordered": false,
|
"using_mrr": false,
|
"index_only": false,
|
"rows": 1,
|
"cost": 2.5033,
|
"chosen": true
|
}
|
],
|
"analyzing_index_merge_union": []
|
},
|
"chosen_range_access_summary": {
|
"range_access_plan": {
|
"type": "range_scan",
|
"index": "exptime",
|
"rows": 1,
|
"ranges": ["(NULL) < (exptime) < (2020-11-21 18:06:30)"]
|
},
|
"rows_for_plan": 1,
|
"cost_for_plan": 2.5033,
|
"chosen": true
|
We are not sure if this might be the culprit of our lag, but it is definitely something that has regressed on 10.4.17.
The table schema:
CREATE TABLE `pc000` (
|
`keyname` varbinary(255) NOT NULL DEFAULT '',
|
`value` mediumblob DEFAULT NULL,
|
`exptime` datetime DEFAULT NULL,
|
UNIQUE KEY `keyname` (`keyname`),
|
KEY `exptime` (`exptime`)
|
) ENGINE=InnoDB DEFAULT CHARSET=binary
|
This is being tracked publicly on our tracking system: https://phabricator.wikimedia.org/T268457
Attachments
Issue Links
- duplicates
-
-
- Closed
-
-
-
- Closed
-
Activity
For what is worth, after a few days of running 10.4.18 on one of the hosts, it is performing better than the one doing 10.4.17
Oh, missed this comment. Good!
Closing as Duplicate of MDEV-24438 . Feel free to reopen if something is not resolved.
| If one is upgrading from a version later than 10.4.15, they need to run ANALYZE TABLE or re-load the data to get the good query plan. |
Going to try this, as I still have one 10.4.17 showing the bad query plans. Going to upgrade to 10.4.18 + ANALYZE all its table and will report back
If this works, that's a good approach as we thankfully don't have many more hosts running 10.4.17 since we stopped after noticing this regression.
Confirmed the ANALYZE workaround works when upgrading from 10.4.17 -> 10.4.18.
Thank you for taking the time and effort to investigating this bug - much appreciated.
Re-tried these steps:
on clean 10.4.17 - shows "BAD" explain
on 10.4.17 patched with 5991bd6215054f21ec5c36fc9345ffb50f1b2d04 - shows "Good" explain.
This confirms the above: