Bug #103300 Query response slowness on 5.7 which is taking 0.36 secs and in 5.6 0.00 secs
Submitted: 13 Apr 2021 11:24 Modified: 14 Apr 2021 12:57
Reporter: Selva Balaji Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S5 (Performance)
Version:5.7.33-36-log OS:CentOS
Assigned to: CPU Architecture:x86

[13 Apr 2021 11:24] Selva Balaji
Description:
We have faced performance issue for the following query on 5.7 which is taking 0.36 seconds and where as MySQL 5.6 its executing within 0.0 seconds 
Facing this issue after we upgraded the MySQL from 5.6 to 5.7. 
Query : SELECT uniqueId,`fieldLabel`,`fieldType`,`displayOrder`,`identifier`,IFNULL(`initialFormFieldSpecId`,-1) as initialFieldSpecId,IFNULL(`skeletonFormFieldSpecId`,-1) as skeletonFieldSpecId,`isVisible`, trim(case when (`t9`.`fieldType` in (5,6)) then (select group_concat(`t1`.`value`) from `t1` where `t1`.`valueId` IN (-1)) when (`t9`.`fieldType` = 7) then (select `t2`.`customerName` from `t2` where (`t2`.`customerId` =  'false')) when (`t9`.`fieldType` = 15) then (select concat(`t3`.`empFirstName`,' ',`t3`.`empLastName`) from `t3` where (`t3`.`empId` = 'false')) when (`t9`.`fieldType` = 14) then (SELECT GROUP_CONCAT(e.`displayValue`) as displayValue FROM `t4` e WHERE e.`identifier`=1 and e.`entityId`='false' limit 1) when (`t9`.`fieldType` = 17) then (SELECT group_concat(e.`displayValue`) FROM `t4` e WHERE e.`identifier`=1 and e.`entityId` IN (-1))when (`t9`.`fieldType` = 4) then (if('true'='false','yes','no')) when (`t9`.`fieldType` = 24) then (select customerTypeName from t5 where customerTypeId='false' limit 1) when (`t9`.`fieldType` = 30) then (SELECT group_concat(`t2`.`customerName`) FROM `t2` where `t2`.`customerId` IN (-1)) when (`t9`.`fieldType` = 31) then (select t7.`territoryName` FROM `t7` where (t7.`territoryId` = 'false'))when (`t9`.`fieldType` = 32) then (select t6.`customEntityName` FROM `t6` where (t6.`customEntityId` = 'false'))when (`t9`.`fieldType` = 25) then (SELECT IFNULL(concat(f.`formId`,'-',group_concat(fi.`identifier`)),f.formId) FROM  t8 f LEFT JOIN (select `FormFields`.`formId` AS `formId`,group_concat(`FormFields`.`displayValue` separator ',') AS `identifier` from `FormFields` where (`FormFields`.`identifier` = 1) and formId = 'false' group by formId) AS fi ON f.formId=fi.formId WHERE f.`formId`= 'false') else 'false' end)  as displayValue FROM `t9` WHERE `fieldSpecId`=1957147;

We tried changed  optimizer_search_depth values  on MySQL 5.7, but no luck.

How to repeat:
Please find the query profiling for mysql 5.6 and 5.7 below 

Mysql 5.6
mysql> SHOW PROFILE SOURCE FOR QUERY 1;
+--------------------------------+----------+-----------------------+------------------+-------------+
| Status                         | Duration | Source_function       | Source_file      | Source_line |
+--------------------------------+----------+-----------------------+------------------+-------------+
| starting                       | 0.036983 | NULL                  | NULL             |        NULL |
| Waiting for query cache lock   | 0.000006 | try_lock              | sql_cache.cc     |         668 |
| Waiting on query cache mutex   | 0.000003 | try_lock              | sql_cache.cc     |         672 |
| init                           | 0.000002 | try_lock              | sql_cache.cc     |         668 |
| checking query cache for query | 0.000261 | send_result_to_client | sql_cache.cc     |        1902 |
| checking permissions           | 0.000004 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000002 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000001 | check_access          | sql_parse.cc     |        5952 |
| checking permissions           | 0.000005 | check_access          | sql_parse.cc     |        5952 |
| Opening tables                 | 0.000127 | open_tables           | sql_base.cc      |        5270 |
| init                           | 0.000102 | mysql_prepare_select  | sql_select.cc    |        1058 |
| System lock                    | 0.000019 | mysql_lock_tables     | lock.cc          |         313 |
| Waiting for query cache lock   | 0.000002 | try_lock              | sql_cache.cc     |         668 |
| Waiting on query cache mutex   | 0.000003 | try_lock              | sql_cache.cc     |         672 |
| System lock                    | 0.000101 | try_lock              | sql_cache.cc     |         668 |
| optimizing                     | 0.000006 | optimize              | sql_optimizer.cc |         146 |
| statistics                     | 0.000040 | optimize              | sql_optimizer.cc |         391 |
| preparing                      | 0.000005 | optimize              | sql_optimizer.cc |         514 |
| executing                      | 0.000002 | exec                  | sql_executor.cc  |         117 |
| Sending data                   | 0.000016 | exec                  | sql_executor.cc  |         197 |
| end                            | 0.000005 | mysql_execute_select  | sql_select.cc    |        1113 |
| query end                      | 0.000004 | mysql_execute_command | sql_parse.cc     |        5619 |
| closing tables                 | 0.000003 | mysql_execute_command | sql_parse.cc     |        5699 |
| removing tmp table             | 0.000003 | free_tmp_table        | sql_tmp_table.cc |        1880 |
| closing tables                 | 0.000015 | free_tmp_table        | sql_tmp_table.cc |        1917 |
| freeing items                  | 0.000013 | mysql_parse           | sql_parse.cc     |        7244 |
| Waiting for query cache lock   | 0.000002 | try_lock              | sql_cache.cc     |         668 |
| Waiting on query cache mutex   | 0.000002 | try_lock              | sql_cache.cc     |         672 |
| freeing items                  | 0.000018 | try_lock              | sql_cache.cc     |         668 |
| Waiting for query cache lock   | 0.000002 | try_lock              | sql_cache.cc     |         668 |
| Waiting on query cache mutex   | 0.000001 | try_lock              | sql_cache.cc     |         672 |
| freeing items                  | 0.000002 | try_lock              | sql_cache.cc     |         668 |
| storing result in query cache  | 0.000002 | end_of_result         | sql_cache.cc     |        1239 |
| cleaning up                    | 0.000014 | dispatch_command      | sql_parse.cc     |        1980 |
+--------------------------------+----------+-----------------------+------------------+-------------+
42 rows in set, 1 warning (0.00 sec)

Mysql 5.7
mysql> SHOW PROFILE SOURCE FOR QUERY 1;
+----------------------+----------+-----------------------+----------------------+-------------+
| Status               | Duration | Source_function       | Source_file          | Source_line |
+----------------------+----------+-----------------------+----------------------+-------------+
| starting             | 0.000382 | NULL                  | NULL                 |        NULL |
| checking permissions | 0.000007 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000002 | check_access          | sql_authorization.cc |         817 |
| checking permissions | 0.000005 | check_access          | sql_authorization.cc |         817 |
| Opening tables       | 0.000394 | open_tables           | sql_base.cc          |        5885 |
| init                 | 0.000215 | handle_query          | sql_select.cc        |         128 |
| System lock          | 0.000019 | mysql_lock_tables     | lock.cc              |         330 |
| optimizing           | 0.000011 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000081 | optimize              | sql_optimizer.cc     |         393 |
| preparing            | 0.000012 | optimize              | sql_optimizer.cc     |         501 |
| optimizing           | 0.000003 | optimize              | sql_optimizer.cc     |         158 |
| optimizing           | 0.000005 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000213 | optimize              | sql_optimizer.cc     |         393 |
| preparing            | 0.000185 | optimize              | sql_optimizer.cc     |         501 |
| executing            | 0.000004 | exec                  | sql_executor.cc      |         126 |
| Sending data         | 0.282652 | exec                  | sql_executor.cc      |         202 |
| statistics           | 0.000068 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000006 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000024 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000005 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000033 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000007 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000034 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000004 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000015 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000008 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000097 | optimize              | sql_optimizer.cc     |         393 |
| preparing            | 0.000119 | optimize              | sql_optimizer.cc     |         501 |
| optimizing           | 0.000007 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000039 | optimize              | sql_optimizer.cc     |         393 |
| preparing            | 0.000132 | optimize              | sql_optimizer.cc     |         501 |
| optimizing           | 0.000010 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000031 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000007 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000029 | optimize              | sql_optimizer.cc     |         393 |
| optimizing           | 0.000005 | optimize              | sql_optimizer.cc     |         158 |
| statistics           | 0.000024 | optimize              | sql_optimizer.cc     |         393 |
| executing            | 0.000003 | exec                  | sql_executor.cc      |         126 |
| Sending data         | 0.000038 | exec                  | sql_executor.cc      |         202 |
| end                  | 0.000005 | handle_query          | sql_select.cc        |         207 |
| query end            | 0.000015 | mysql_execute_command | sql_parse.cc         |        5265 |
| removing tmp table   | 0.000009 | free_tmp_table        | sql_tmp_table.cc     |        2423 |
| query end            | 0.000005 | free_tmp_table        | sql_tmp_table.cc     |        2460 |
| removing tmp table   | 0.000004 | free_tmp_table        | sql_tmp_table.cc     |        2423 |
| query end            | 0.000002 | free_tmp_table        | sql_tmp_table.cc     |        2460 |
| removing tmp table   | 0.000003 | free_tmp_table        | sql_tmp_table.cc     |        2423 |
| query end            | 0.000003 | free_tmp_table        | sql_tmp_table.cc     |        2460 |
| closing tables       | 0.000005 | mysql_execute_command | sql_parse.cc         |        5344 |
| removing tmp table   | 0.000055 | free_tmp_table        | sql_tmp_table.cc     |        2423 |
| closing tables       | 0.000028 | free_tmp_table        | sql_tmp_table.cc     |        2460 |
| freeing items        | 0.000066 | mysql_parse           | sql_parse.cc         |        5965 |
| cleaning up          | 0.000022 | dispatch_command      | sql_parse.cc         |        1991 |
+----------------------+----------+-----------------------+----------------------+-------------+
61 rows in set, 1 warning (0.00 sec)

In profiling sending data is taking more time in mysql 5.7 

Explain plan is same for both 5.6 and 5.7.

We created one index on 5.7 and response time is now 0.05 secs. 

We also tried the optimized hint which is not helping us to improve the performance, no luck.
[14 Apr 2021 12:57] MySQL Verification Team
Hi Mr. Balaji,

Thank you for your bug report.

However, it is not a bug.

It is very well known fact that single-thread performance has dropped between 5.6 and 5.7 and also between 5.7 and 8.0.

Next, difference in time is so small, that it is not prone to any analysis.

Last, but not least, this could be caused by query cache, which is deprecated long time ago.

Not a bug.