Bug #79547 bad performance query on mysql 5.6
Submitted: 7 Dec 2015 13:59 Modified: 2 Jun 2019 13:54
Reporter: walter verdelocco Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S3 (Non-critical)
Version:5.6 OS:Debian
Assigned to: CPU Architecture:Any
Tags: Optimizer, performance, query

[7 Dec 2015 13:59] walter verdelocco 
Description:
Hi 

i have a problem with a query after migration on mysql5.6 
on mysql 5.5 all works fine the query is executed in 37 millisecs , 
the same query on 5.6 is too long 29 seconds!!! 

I havd replicated my envs , so i have 
2 databases (5.5.46 and 5.6.25 ) with the same data 
and the same configuration parameters 

the query is: 
SELECT messaggio.id, messaggio.data, allegati.id 
FROM ( 
select m.id from messaggio m 
WHERE m.idarticolo='repnews_271330' AND m.idpadre=0 
AND m.pubblica=1 ORDER BY m.data DESC LIMIT 50 
) as m_padre 
join messaggio on (m_padre.id=messaggio.idpadre OR m_padre.id=messaggio.id) 
left join allegati on messaggio.id = allegati.idpost 
ORDER BY messaggio.data DESC, messaggio.id desc, allegati.id asc; 

explain on 5.5 is: 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+----------------------------+---------+-------------------------------------------------+ 
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+----------------------------+---------+-------------------------------------------------+ 
| 1 | PRIMARY | <derived2> | ALL | NULL | NULL | NULL | NULL | 27 | Using temporary; Using filesort | 
| 1 | PRIMARY | messaggio | ALL | PRIMARY,idpadre,idpadrepubblica_idx,ididpadrepubblica | NULL | NULL | NULL | 2357872 | Range checked for each record (index map: 0x65) | 
| 1 | PRIMARY | allegati | ref | idpost_idx | idpost_idx | 5 | DROPME_ts_mms.messaggio.id | 1 | Using index | 
| 2 | DERIVED | m | ALL | idpadre,idpadrepubblica_idx,idarticolo_idx | idarticolo_idx | 130 | | 2357872 | Using where; Using filesort | 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+----------------------------+---------+-------------------------------------------------+ 

explain on 5.6: 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+------------------------------+---------+----------------------------------------------------+ 
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+------------------------------+---------+----------------------------------------------------+ 
| 1 | PRIMARY | messaggio | ALL | PRIMARY,idpadre,idpadrepubblica_idx,ididpadrepubblica | NULL | NULL | NULL | 2445095 | Using temporary; Using filesort | 
| 1 | PRIMARY | allegati | ref | idpost_idx | idpost_idx | 5 | DROPME_ts_mms56.messaggio.id | 1 | Using index | 
| 1 | PRIMARY | <derived2> | ALL | NULL | NULL | NULL | NULL | 26 | Using where; Using join buffer (Block Nested Loop) | 
| 2 | DERIVED | m | ref | idpadre,idpadrepubblica_idx,idarticolo_idx | idarticolo_idx | 130 | const | 26 | Using index condition; Using where; Using filesort | 
+----+-------------+------------+------+-------------------------------------------------------+----------------+---------+------------------------------+---------+----------------------------------------------------+ 

How to repeat:
--
[7 Dec 2015 13:59] walter verdelocco 
-- profioling the query i see: 
on 5.5 
mysql> show profiles\G; 
*************************** 1. row *************************** 
Query_ID: 1 
Duration: 0.00376525 
Query: SELECT messaggio.id, messaggio.data, allegati.id 
FROM ( 
select m.id from messaggio m 
WHERE m.idarticolo='repnews_271330' AND m.idpadre=0 
AND m.pubblica=1 
ORDER BY m.data DESC 
LIMIT 50 
) as m_padre 
join messaggio on (m_padre.id=messaggio.idpadre OR m_padre.id=messag 
1 row in set (0.00 sec) 

ERROR: 
No query specified 

mysql> select min(seq) seq,state,count(*) numb_ops, 
-> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur, 
-> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu 
-> from information_schema.profiling 
-> where query_id = 1 
-> group by state 
-> order by seq; 
+------+----------------------+----------+---------+---------+---------+---------+ 
| seq | state | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu | 
+------+----------------------+----------+---------+---------+---------+---------+ 
| 2 | starting | 1 | 0.00018 | 0.00018 | 0.00016 | 0.00016 | 
| 3 | checking permissions | 3 | 0.00002 | 0.00001 | 0.00001 | 0.00000 | 
| 6 | Opening tables | 1 | 0.00005 | 0.00005 | 0.00004 | 0.00004 | 
| 7 | System lock | 1 | 0.00009 | 0.00009 | 0.00009 | 0.00009 | 
| 8 | optimizing | 2 | 0.00003 | 0.00002 | 0.00003 | 0.00002 | 
| 9 | statistics | 2 | 0.00020 | 0.00010 | 0.00020 | 0.00010 | 
| 10 | preparing | 2 | 0.00007 | 0.00003 | 0.00006 | 0.00003 | 
| 11 | executing | 2 | 0.00001 | 0.00001 | 0.00001 | 0.00000 | 
| 12 | Sorting result | 2 | 0.00021 | 0.00011 | 0.00021 | 0.00010 | 
| 13 | Sending data | 2 | 0.00007 | 0.00004 | 0.00007 | 0.00003 | 
| 14 | init | 1 | 0.00003 | 0.00003 | 0.00003 | 0.00003 | 
| 18 | Creating tmp table | 1 | 0.00003 | 0.00003 | 0.00003 | 0.00003 | 
| 20 | Copying to tmp table | 1 | 0.00266 | 0.00266 | 0.00258 | 0.00258 | 
| 23 | end | 2 | 0.00001 | 0.00001 | 0.00001 | 0.00000 | 
| 24 | removing tmp table | 2 | 0.00002 | 0.00001 | 0.00001 | 0.00001 | 
| 26 | query end | 1 | 0.00001 | 0.00001 | 0.00001 | 0.00001 | 
| 27 | closing tables | 2 | 0.00002 | 0.00001 | 0.00002 | 0.00001 | 
| 30 | freeing items | 1 | 0.00004 | 0.00004 | 0.00002 | 0.00002 | 
| 31 | logging slow query | 1 | 0.00001 | 0.00001 | 0.00001 | 0.00001 | 
| 32 | cleaning up | 1 | 0.00001 | 0.00001 | 0.00001 | 0.00001 | 
+------+----------------------+----------+---------+---------+---------+---------+ 
20 rows in set (0.00 sec) 

-- on 5.6 
mysql> show profiles\G; 
*************************** 1. row *************************** 
Query_ID: 1 
Duration: 28.96773375 
Query: SELECT messaggio.id, messaggio.data, allegati.id 
FROM ( 
select m.id from messaggio m 
WHERE m.idarticolo='repnews_271330' AND m.idpadre=0 
AND m.pubblica=1 
ORDER BY m.data DESC 
LIMIT 50 
) as m_padre 
join messaggio on (m_padre.id=messaggio.idpadre OR m_padre.id=messag 
1 row in set, 1 warning (0.00 sec) 

ERROR: 
No query specified 

mysql> select min(seq) seq,state,count(*) numb_ops, 
-> round(sum(duration),5) sum_dur, round(avg(duration),5) avg_dur, 
-> round(sum(cpu_user),5) sum_cpu, round(avg(cpu_user),5) avg_cpu 
-> from information_schema.profiling 
-> where query_id = 1 
-> group by state 
-> order by seq; 
+------+----------------------+----------+----------+----------+----------+----------+ 
| seq | state | numb_ops | sum_dur | avg_dur | sum_cpu | avg_cpu | 
+------+----------------------+----------+----------+----------+----------+----------+ 
| 2 | starting | 1 | 0.00020 | 0.00020 | 0.00017 | 0.00017 | 
| 3 | checking permissions | 3 | 0.00002 | 0.00001 | 0.00001 | 0.00000 | 
| 6 | Opening tables | 1 | 0.00010 | 0.00010 | 0.00010 | 0.00010 | 
| 7 | init | 1 | 0.00003 | 0.00003 | 0.00003 | 0.00003 | 
| 8 | System lock | 1 | 0.00002 | 0.00002 | 0.00002 | 0.00002 | 
| 9 | optimizing | 2 | 0.00003 | 0.00001 | 0.00002 | 0.00001 | 
| 11 | statistics | 2 | 0.00026 | 0.00013 | 0.00025 | 0.00013 | 
| 12 | preparing | 2 | 0.00008 | 0.00004 | 0.00007 | 0.00004 | 
| 13 | Sorting result | 2 | 0.00003 | 0.00001 | 0.00002 | 0.00001 | 
| 16 | Creating tmp table | 1 | 0.00003 | 0.00003 | 0.00002 | 0.00002 | 
| 18 | executing | 2 | 0.00003 | 0.00001 | 0.00002 | 0.00001 | 
| 19 | Sending data | 2 | 0.00007 | 0.00003 | 0.00006 | 0.00003 | 
| 22 | Creating sort index | 2 | 28.96662 | 14.48331 | 28.96593 | 14.48296 | 
| 24 | end | 2 | 0.00002 | 0.00001 | 0.00001 | 0.00001 | 
| 25 | removing tmp table | 2 | 0.00002 | 0.00001 | 0.00002 | 0.00001 | 
| 27 | query end | 1 | 0.00001 | 0.00001 | 0.00001 | 0.00001 | 
| 28 | closing tables | 2 | 0.00003 | 0.00002 | 0.00003 | 0.00001 | 
| 31 | freeing items | 1 | 0.00005 | 0.00005 | 0.00003 | 0.00003 | 
| 32 | logging slow query | 1 | 0.00009 | 0.00009 | 0.00005 | 0.00005 | 
| 33 | cleaning up | 1 | 0.00003 | 0.00003 | 0.00002 | 0.00002 | 
+------+----------------------+----------+----------+----------+----------+----------+ 
20 rows in set (0.00 sec) 

so i see 
22 | Creating sort index | 2 | 28.96662 | 14.48331 | 28.96593 | 14.48296 |
[9 Dec 2015 16:06] walter verdelocco 
i have opened an issue on.forum.mysql 
where it's possible read other information .. 

http://forums.mysql.com/read.php?24,639446,639446#msg-639446

i can give some information about tables  messaggio and allegati :

mysql> SHOW TABLE STATUS FROM `DROPME_ts_mms56` LIKE 'messaggio'\G;
*************************** 1. row ***************************
           Name: messaggio
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 2445095
 Avg_row_length: 527
    Data_length: 1290797056
Max_data_length: 0
   Index_length: 1858715648
      Data_free: 6291456
 Auto_increment: 2961078
    Create_time: 2015-12-03 14:04:40
    Update_time: NULL
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.02 sec)

ERROR:
No query specified

mysql> SHOW CREATE TABLE `DROPME_ts_mms56`.`messaggio`\G;
*************************** 1. row ***************************
       Table: messaggio
Create Table: CREATE TABLE `messaggio` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `idevento` int(11) NOT NULL DEFAULT '0',
  `idarticolo` varchar(128) NOT NULL DEFAULT '',
  `idbrand` int(11) NOT NULL DEFAULT '0',
  `idmms` varchar(50) DEFAULT NULL,
  `nome` varchar(250) DEFAULT NULL,
  `commento` longtext,
  `titolo` tinytext,
  `email` varchar(50) DEFAULT NULL,
  `pubblica` int(1) NOT NULL DEFAULT '0',
  `ip` varchar(16) NOT NULL DEFAULT '',
  `data` int(14) NOT NULL DEFAULT '0',
  `idpadre` int(11) NOT NULL DEFAULT '0',
  `tot_voti` int(11) DEFAULT '0',
  `votanti` int(11) DEFAULT '0',
  `voti_si` int(11) DEFAULT '0',
  `voti_no` int(11) DEFAULT '0',
  `segnalazioni` int(10) unsigned NOT NULL DEFAULT '0',
  `idUtente` int(11) unsigned DEFAULT NULL,
  `ordine` int(11) DEFAULT NULL,
  `num_click` int(11) DEFAULT '0',
  `miscellanea` mediumtext,
  `data_creazione` int(14) NOT NULL DEFAULT '0',
  PRIMARY KEY (`id`),
  KEY `idevento_idx` (`idevento`),
  KEY `idpadre` (`idpadre`),
  KEY `ideventoidpadre_idx` (`idevento`,`idpadre`),
  KEY `ideventoidpadrepubblica_idx` (`idevento`,`idpadre`,`pubblica`),
  KEY `idpadrepubblica_idx` (`idpadre`,`pubblica`),
  KEY `ididpadrepubblica` (`id`,`idpadre`,`pubblica`),
  KEY `idUtente_idx` (`idUtente`),
  KEY `data_idx` (`data`),
  KEY `nome` (`nome`),
  KEY `idbrand_idx` (`idbrand`),
  KEY `idarticolo_idx` (`idarticolo`),
  KEY `commento_ft_idx` (`commento`(500)),
  KEY `titolo_ft_idx` (`titolo`(200))
) ENGINE=InnoDB AUTO_INCREMENT=2961078 DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

ERROR:
No query specified

mysql>
mysql> SHOW TABLE STATUS FROM `DROPME_ts_mms56` LIKE 'allegati'\G;
*************************** 1. row ***************************
           Name: allegati
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 400357
 Avg_row_length: 224
    Data_length: 89767936
Max_data_length: 0
   Index_length: 51478528
      Data_free: 5242880
 Auto_increment: 499694
    Create_time: 2015-12-03 14:39:28
    Update_time: NULL
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.01 sec)

ERROR:
No query specified

mysql> SHOW CREATE TABLE `DROPME_ts_mms56`.`allegati`\G;
*************************** 1. row ***************************
       Table: allegati
Create Table: CREATE TABLE `allegati` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `idpost` int(11) DEFAULT '0',
  `dir` varchar(255) DEFAULT NULL,
  `size` int(11) DEFAULT NULL,
  `tipo` varchar(50) DEFAULT NULL,
  `tipo_originale` varchar(50) DEFAULT NULL,
  `nome` varchar(50) DEFAULT NULL,
  `encoding` int(1) NOT NULL DEFAULT '0',
  `encodingTaskId` int(32) NOT NULL DEFAULT '0',
  `nomeEncoded` varchar(255) DEFAULT NULL,
  `idUpload` varchar(32) DEFAULT NULL,
  `tipo_generico` varchar(50) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idpost_idx` (`idpost`),
  KEY `ididpost_idx` (`id`,`idpost`),
  KEY `tipo_idx` (`tipo`),
  KEY `tipo_generico_idx` (`tipo_generico`)
) ENGINE=InnoDB AUTO_INCREMENT=499694 DEFAULT CHARSET=latin1
1 row in set (0.00 sec)
[11 Dec 2015 12:12] Øystein Grøvlen 
Optimizer trace for default settings (copied from MySQL Performance Forum)

Attachment: bnl.trace (application/octet-stream, text), 19.43 KiB.
[11 Dec 2015 12:25] Øystein Grøvlen 
Optimizer trace when BNL is off (copied from MySQL Performance Forum))

Attachment: no-bnl.trace (application/octet-stream, text), 30.18 KiB.
[2 May 2019 13:54] MySQL Verification Team 
Please check with most recent version 5.7/8.0. Thanks.
[3 Jun 2019 1:00] Bugs System 
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".