| Bug #87164 | Queries running much slower in version 5.7 versus 5.6 | ||
|---|---|---|---|
| Submitted: | 21 Jul 2017 16:28 | Modified: | 19 Apr 2018 5:46 |
| Reporter: | Alok Pathak | Email Updates: | |
| Status: | Won't fix | Impact on me: | |
| Category: | MySQL Server: Optimizer | Severity: | S3 (Non-critical) |
| Version: | 5.7, 5.7.18, 5.7.19 | OS: | CentOS (6 & 7) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | regression | ||
[21 Jul 2017 17:59]
MySQL Verification Team
Thank you for the bug report. Please check with MySQL released binaries: https://dev.mysql.com/downloads/ Thanks in advance.
[22 Jul 2017 10:19]
Alok Pathak
Hi Miguel,
I tested query with MySQL 5.6 and 5.7 binaries and getting same behaviour. 5.7 takes 3 minutes while 5.6 takes only 0.63 sec.
Following are the results for review.
# 5.6
Server version: 5.6.37-log MySQL Community Server (GPL)
{VagrantVM_56} percona> source /vagrant/query.sql
4e7de9588cf969744efd83760610f2b5 -
8 rows in set (0.63 sec)
{VagrantVM_56} percona> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.034791 |
| checking permissions | 0.000013 |
| checking permissions | 0.000002 |
| checking permissions | 0.000002 |
| checking permissions | 0.000001 |
| checking permissions | 0.000006 |
| Opening tables | 0.000030 |
| init | 0.009556 |
| System lock | 0.000028 |
| optimizing | 0.001239 |
| statistics | 0.584782 |
| preparing | 0.001294 |
| Creating tmp table | 0.000051 |
| Sorting result | 0.000006 |
| executing | 0.000004 |
| Sending data | 0.002064 |
| Creating sort index | 0.000045 |
| end | 0.000005 |
| removing tmp table | 0.000007 |
| end | 0.000005 |
| query end | 0.000010 |
| closing tables | 0.000019 |
| freeing items | 0.000347 |
| cleaning up | 0.000018 |
+----------------------+----------+
24 rows in set, 1 warning (0.01 sec)
# 5.7
Server version: 5.7.19-log MySQL Community Server (GPL)
{VagrantVM_57} percona> source /vagrant/query.sql
4e7de9588cf969744efd83760610f2b5 -
8 rows in set (3 min 2.49 sec)
Query is spending almost all time in statistics state.
{VagrantVM_57} percona> show profile for query 1;
+----------------------+------------+
| Status | Duration |
+----------------------+------------+
| starting | 0.069121 |
| checking permissions | 0.000023 |
| checking permissions | 0.000003 |
| checking permissions | 0.000003 |
| checking permissions | 0.000003 |
| checking permissions | 0.000009 |
| Opening tables | 0.000128 |
| init | 0.004157 |
| System lock | 0.000039 |
| optimizing | 0.003115 |
| statistics | 182.396708 |
| preparing | 0.001067 |
| Creating tmp table | 0.000046 |
| Sorting result | 0.000007 |
| executing | 0.000003 |
| Sending data | 0.009779 |
| Creating sort index | 0.000068 |
| end | 0.000006 |
| query end | 0.000011 |
| removing tmp table | 0.000007 |
| query end | 0.000003 |
| closing tables | 0.000011 |
| freeing items | 0.000480 |
| cleaning up | 0.000025 |
+----------------------+------------+
24 rows in set, 1 warning (0.03 sec)
I changed optimizer_switch to make it same as 5.6 but that didn't help.
{VagrantVM_57} percona> set session optimizer_switch ="index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,engine_condition_pushdown=on,index_condition_pushdown=on,mrr=on,mrr_cost_based=on,block_nested_loop=on,batched_key_access=off,materialization=on,semijoin=on,loosescan=on,firstmatch=on,duplicateweedout=off,subquery_materialization_cost_based=on,use_index_extensions=on,condition_fanout_filter=off,derived_merge=off";
Query OK, 0 rows affected (0.02 sec)
{VagrantVM_57} percona> source /vagrant/query.sql
4e7de9588cf969744efd83760610f2b5 -
8 rows in set (3 min 0.74 sec)
{VagrantVM_57} percona> show profile for query 4;
+----------------------+------------+
| Status | Duration |
+----------------------+------------+
| starting | 0.008862 |
| checking permissions | 0.000013 |
| checking permissions | 0.000002 |
| checking permissions | 0.000002 |
| checking permissions | 0.000002 |
| checking permissions | 0.000005 |
| Opening tables | 0.000030 |
| init | 0.002925 |
| System lock | 0.000045 |
| optimizing | 0.001354 |
| statistics | 180.718277 |
| preparing | 0.000940 |
| Creating tmp table | 0.000043 |
| Sorting result | 0.000007 |
| executing | 0.000002 |
| Sending data | 0.006890 |
| Creating sort index | 0.000045 |
| end | 0.000004 |
| query end | 0.000022 |
| removing tmp table | 0.000006 |
| query end | 0.000003 |
| closing tables | 0.000009 |
| freeing items | 0.000518 |
| cleaning up | 0.000035 |
+----------------------+------------+
24 rows in set, 1 warning (0.00 sec)
Please let me know if you need any further information.
[22 Jul 2017 14:05]
MySQL Verification Team
Related bug reports: https://bugs.mysql.com/bug.php?id=75981 https://bugs.mysql.com/bug.php?id=86215
[24 Jul 2017 8:24]
MySQL Verification Team
Thank you for the report.
[24 Jul 2017 8:25]
MySQL Verification Team
5.6.37 vs 5.7.19 - results
Attachment: 87164.results (application/octet-stream, text), 31.67 KiB.
[24 Jul 2017 14:28]
Øystein Grøvlen
What is the setting for eq_range_index_dive_limit ?
[24 Jul 2017 22:38]
Øystein Grøvlen
Workaround: Use optimizer hint /*+ NO_RANGE_OPTIMIZATION(pc2) */ to turn off range optimization for table pc2.
[25 Jul 2017 7:54]
Alok Pathak
Hi,
eq_range_index_dive_limit is set to default value i.e. 200.
{VagrantVM_57} (none)> show global variables like "%eq_range_index_dive_limit%";
+---------------------------+-------+
| Variable_name | Value |
+---------------------------+-------+
| eq_range_index_dive_limit | 200 |
+---------------------------+-------+
1 row in set (0.00 sec)
I'll try workaround and share the results.
Thank you.
[25 Jul 2017 13:16]
Alok Pathak
Hi Øystein,
Thank you for the workaround.
With the help of optimizer hint, query is taking only 0.46 second now.
Server version: 5.7.19-log MySQL Community Server (GPL)
{VagrantVM_57} percona> source /vagrant/query.sql.workaround
4e7de9588cf969744efd83760610f2b5 -
8 rows in set (0.46 sec)
{VagrantVM_57} percona> show profile for query 1;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.035290 |
| checking permissions | 0.000018 |
| checking permissions | 0.000002 |
| checking permissions | 0.000002 |
| checking permissions | 0.000002 |
| checking permissions | 0.000006 |
| Opening tables | 0.000123 |
| init | 0.009024 |
| System lock | 0.000066 |
| optimizing | 0.001641 |
| statistics | 0.403092 |
| preparing | 0.000872 |
| Creating tmp table | 0.000037 |
| Sorting result | 0.000006 |
| executing | 0.000002 |
| Sending data | 0.010237 |
| Creating sort index | 0.000060 |
| end | 0.000004 |
| query end | 0.000010 |
| removing tmp table | 0.000005 |
| query end | 0.000003 |
| closing tables | 0.000010 |
| freeing items | 0.000394 |
| cleaning up | 0.002052 |
+----------------------+----------+
24 rows in set, 1 warning (0.02 sec)
Can you please highlight why it's taking 3 minutes with default settings. Is this expected behaviour with 5.7 and high number of ids in where clause? pc2 has two conditions in where clause, first one has 8K and second condition has 600 ids with IN (N,N,N....N).
Thanks in advance.
[25 Jul 2017 20:18]
Øystein Grøvlen
Hi Alok, I have not had time to study this in detail yet, and I am not sure what caused the change from 5.6 to 5.7. However, I think the issue is that the range optimizer tries to enumerate every combination of values from the 2 columns. In this case, this means 4.8 million ranges that needs to be optimized.
[26 Jul 2017 13:47]
Alok Pathak
Hi Øystein, Thank you for the update. It would be great if we can find the root cause of this problem and this bug can be fixed in upcoming minor releases of 5.7. Please update when you've more information on this. Thanks in advance.
[31 Jul 2017 12:29]
ashe sun
hello, @Alok Pathak can you send the testing sql to me ? I want debug it and try to get the reason.
[2 Aug 2017 11:24]
ashe sun
where is the dump.sql ? I want it to repeat, thank you a lot
[8 Aug 2017 7:23]
Alok Pathak
dump.sql with tables and data
Attachment: dump.sql.zip (application/zip, text), 1.78 MiB.
[8 Aug 2017 7:23]
Alok Pathak
Query which takes long on 5.7
Attachment: query.sql.zip (application/zip, text), 31.34 KiB.
[8 Aug 2017 7:26]
Alok Pathak
@ashe, I've attached dump.sql.zip file which has tables structure, data and query.sql.zip which has query. Please let me know your findings.
[22 Aug 2017 13:00]
Alok Pathak
Hi Øystein, Ashe, Please let me know if you've any update on this bug.
[7 Feb 2018 21:18]
Dmitry V
Hi, any update on this issue?
[19 Apr 2018 5:39]
Sreeharsha Ramanavarapu
Posted by developer: Posting to external bugpage: This issue was fixed in 8.0 as part of Bug#22671573. Please upgrade to 8.0 GA version to avoid this problem. Workaround for 5.7 would be to add "IGNORE INDEX(idx_family_unique)" to the query. This will avoid the building of the problematic RB-tree thereby side-stepping the problem.
[13 Apr 2021 7:43]
Selva Balaji
We tried with optimize hint as well, Same issue. Query is very slow while comparing with 5.6.
[13 Apr 2021 7:44]
Selva Balaji
Query taking 0.3 secs in 5.7 and 0.00 sec in 5.6. Any other optimization required.
Description: After upgrading to MySQL 5.7, some queries are running very slow, taking abnormally long time in statistics state. When I run this query in 5.6, it finish in less than a second but on MySQL 5.7 it's taking approx 3 minutes. I'm running 5.7 and 5.6 with default configuration and binary logs enabled. # 5.6 Server version: 5.6.36-82.0-log Percona Server (GPL), Release 82.0, Revision 58e846a {VagrantVM_56} percona> source /vagrant/query.sql 4e7de9588cf969744efd83760610f2b5 - 8 rows in set (0.78 sec) {VagrantVM_56} percona> show profile for query 7; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.007629 | | checking permissions | 0.000008 | | checking permissions | 0.000001 | | checking permissions | 0.000002 | | checking permissions | 0.000001 | | checking permissions | 0.000004 | | Opening tables | 0.000031 | | init | 0.004538 | | System lock | 0.000024 | | optimizing | 0.001304 | | statistics | 0.763190 | | preparing | 0.001422 | | Creating tmp table | 0.000027 | | Sorting result | 0.000002 | | executing | 0.000003 | | Sending data | 0.002941 | | Creating sort index | 0.000033 | | end | 0.000003 | | removing tmp table | 0.000006 | | end | 0.000014 | | query end | 0.000006 | | closing tables | 0.000016 | | freeing items | 0.000320 | | cleaning up | 0.000028 | +----------------------+----------+ 24 rows in set, 1 warning (0.00 sec) # 5.7 Server version: 5.7.18-15-log Percona Server (GPL), Release 15, Revision bff2cd9 {VagrantVM_57} percona> source /vagrant/query.sql 4e7de9588cf969744efd83760610f2b5 - 8 rows in set (2 min 56.65 sec) Looking at the profiling output, it spends almost all time in statistics state. {VagrantVM_57} percona> show profile for query 3; +----------------------+------------+ | Status | Duration | +----------------------+------------+ | starting | 0.053269 | | checking permissions | 0.000018 | | checking permissions | 0.000002 | | checking permissions | 0.000002 | | checking permissions | 0.000001 | | checking permissions | 0.000014 | | Opening tables | 0.000173 | | init | 0.006661 | | System lock | 0.000037 | | optimizing | 0.001893 | | statistics | 176.579146 | | preparing | 0.000768 | | Creating tmp table | 0.000043 | | Sorting result | 0.000009 | | executing | 0.000001 | | Sending data | 0.007179 | | Creating sort index | 0.000040 | | end | 0.000003 | | query end | 0.000007 | | removing tmp table | 0.000005 | | query end | 0.000002 | | closing tables | 0.000009 | | freeing items | 0.000319 | | cleaning up | 0.000018 | +----------------------+------------+ 24 rows in set, 1 warning (0.02 sec) I changed optimizer_switch to make it same as 5.6 but query still takes same amount of time. {VagrantVM_57} percona> set session optimizer_switch='index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,engine_condition_pushdown=on,index_condition_pushdown=on,mrr=on,mrr_cost_based=on,block_nested_loop=on,batched_key_access=off,materialization=on,semijoin=on,loosescan=on,firstmatch=on,duplicateweedout=off,subquery_materialization_cost_based=on,use_index_extensions=on,condition_fanout_filter=off,derived_merge=off'; Query OK, 0 rows affected (0.04 sec) {VagrantVM_57} percona> source /vagrant/query.sql 4e7de9588cf969744efd83760610f2b5 - 8 rows in set (2 min 51.58 sec) {VagrantVM_57} percona> show profile for query 7; +----------------------+------------+ | Status | Duration | +----------------------+------------+ | starting | 0.007646 | | checking permissions | 0.000007 | | checking permissions | 0.000001 | | checking permissions | 0.000000 | | checking permissions | 0.000001 | | checking permissions | 0.000004 | | Opening tables | 0.004927 | | init | 0.013115 | | System lock | 0.003437 | | optimizing | 0.001046 | | statistics | 171.536144 | | preparing | 0.001881 | | Creating tmp table | 0.000045 | | Sorting result | 0.000007 | | executing | 0.000001 | | Sending data | 0.009277 | | Creating sort index | 0.000061 | | end | 0.000004 | | query end | 0.000011 | | removing tmp table | 0.000005 | | query end | 0.000002 | | closing tables | 0.000012 | | freeing items | 0.000379 | | cleaning up | 0.000021 | +----------------------+------------+ 24 rows in set, 1 warning (0.01 sec) How to repeat: 1. Import dump.sql into MySQL 5.7 instance. 2. Run query.sql and review the execution time. dump.sql and query.sql files are attached to the bug report in compressed .zip format.