MySQL Bugs: #82133: The optimizer is incorrectly using join buffer (Block Nested Loop)

Bug #82133	The optimizer is incorrectly using join buffer (Block Nested Loop)
Submitted:	6 Jul 2016 21:16	Modified:	18 Aug 2016 12:53
Reporter:	monty solomon	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S2 (Serious)
Version:	5.7.12	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
On MySQL 5.7 some queries are taking over 2.5 minutes to execute. The same queries take less than a second to execute on MySQL 5.6.

How to repeat:
Execute the query and observe the execution time.

Explain output for MySQL 5.7

mysql> explain for connection 5431\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: <subquery2>
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: NULL
     filtered: 100.00
        Extra: Using temporary; Using filesort
*************************** 2. row ***************************
           id: 1
  select_type: SIMPLE
        table: u
   partitions: NULL
         type: ALL
possible_keys: PRIMARY
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 2475852
     filtered: 0.00
        Extra: Using where; Using join buffer (Block Nested Loop)
*************************** 3. row ***************************
           id: 2
  select_type: MATERIALIZED
        table: r
   partitions: NULL
         type: ref
possible_keys: PRIMARY,portalId
          key: portalId
      key_len: 5
          ref: const
         rows: 1
     filtered: 100.00
        Extra: Using index
*************************** 4. row ***************************
           id: 2
  select_type: MATERIALIZED
        table: p
   partitions: NULL
         type: ref
possible_keys: uniq_perm,realmId,active,userId
          key: realmId
      key_len: 5
          ref: SkyNet.r.ID,const
         rows: 8
     filtered: 100.00
        Extra: NULL
4 rows in set (0.00 sec)

Sample query times from the slow logs

# Query_time: 173.415100  Lock_time: 0.000081  Rows_sent: 1  Rows_examined: 2562509  Rows_affected: 0
# Query_time: 155.158079  Lock_time: 0.000088  Rows_sent: 11  Rows_examined: 2562528  Rows_affected: 0
# Query_time: 154.123320  Lock_time: 0.000077  Rows_sent: 1361  Rows_examined: 2563889  Rows_affected: 0
# Query_time: 164.990889  Lock_time: 0.000369  Rows_sent: 1361  Rows_examined: 2563904  Rows_affected: 0
# Query_time: 155.173333  Lock_time: 0.000079  Rows_sent: 1360  Rows_examined: 2563900  Rows_affected: 0
# Query_time: 160.099434  Lock_time: 0.000081  Rows_sent: 11  Rows_examined: 2562568  Rows_affected: 0
# Query_time: 154.443839  Lock_time: 0.000074  Rows_sent: 1359  Rows_examined: 2563905  Rows_affected: 0
# Query_time: 154.440674  Lock_time: 0.000079  Rows_sent: 1359  Rows_examined: 2563926  Rows_affected: 0
# Query_time: 154.260571  Lock_time: 0.000084  Rows_sent: 1359  Rows_examined: 2563941  Rows_affected: 0
# Query_time: 155.258852  Lock_time: 0.000087  Rows_sent: 11  Rows_examined: 2562603  Rows_affected: 0
# Query_time: 155.556502  Lock_time: 0.000089  Rows_sent: 11  Rows_examined: 2562622  Rows_affected: 0
# Query_time: 155.589270  Lock_time: 0.000083  Rows_sent: 1026  Rows_examined: 2563642  Rows_affected: 0
# Query_time: 162.176375  Lock_time: 0.000168  Rows_sent: 1359  Rows_examined: 2563992  Rows_affected: 0
# Query_time: 175.374195  Lock_time: 0.000091  Rows_sent: 11  Rows_examined: 2562781  Rows_affected: 0
# Query_time: 163.109873  Lock_time: 0.000112  Rows_sent: 1361  Rows_examined: 2564409  Rows_affected: 0
# Query_time: 154.918675  Lock_time: 0.000085  Rows_sent: 1361  Rows_examined: 2564421  Rows_affected: 0
# Query_time: 159.729592  Lock_time: 0.000098  Rows_sent: 1361  Rows_examined: 2564433  Rows_affected: 0
# Query_time: 155.798285  Lock_time: 0.000084  Rows_sent: 11  Rows_examined: 2563090  Rows_affected: 0
# Query_time: 163.571693  Lock_time: 0.000176  Rows_sent: 11  Rows_examined: 2563106  Rows_affected: 0
# Query_time: 156.595740  Lock_time: 0.000120  Rows_sent: 1361  Rows_examined: 2564464  Rows_affected: 0
# Query_time: 155.517185  Lock_time: 0.000087  Rows_sent: 1362  Rows_examined: 2564498  Rows_affected: 0
# Query_time: 263.744317  Lock_time: 0.000081  Rows_sent: 2307  Rows_examined: 2578137  Rows_affected: 0
# Query_time: 263.425281  Lock_time: 0.000154  Rows_sent: 2307  Rows_examined: 2578158  Rows_affected: 0
# Query_time: 162.441920  Lock_time: 0.000086  Rows_sent: 1363  Rows_examined: 2564568  Rows_affected: 0
# Query_time: 156.951773  Lock_time: 0.000119  Rows_sent: 11  Rows_examined: 2563225  Rows_affected: 0
# Query_time: 162.186248  Lock_time: 0.000115  Rows_sent: 1363  Rows_examined: 2564583  Rows_affected: 0
# Query_time: 277.950661  Lock_time: 0.000105  Rows_sent: 2307  Rows_examined: 2578196  Rows_affected: 0
# Query_time: 262.100554  Lock_time: 0.000570  Rows_sent: 2307  Rows_examined: 2578196  Rows_affected: 0
# Query_time: 156.485652  Lock_time: 0.000079  Rows_sent: 1363  Rows_examined: 2564620  Rows_affected: 0
# Query_time: 261.234357  Lock_time: 0.000076  Rows_sent: 2307  Rows_examined: 2578238  Rows_affected: 0

# Query_time: 161.725538  Lock_time: 0.000089  Rows_sent: 1363  Rows_examined: 2564610  Rows_affected: 0
# Query_time: 154.530262  Lock_time: 0.000176  Rows_sent: 11  Rows_examined: 2563270  Rows_affected: 0
# Query_time: 168.060222  Lock_time: 0.000176  Rows_sent: 11  Rows_examined: 2563286  Rows_affected: 0
# Query_time: 168.481856  Lock_time: 0.000083  Rows_sent: 1363  Rows_examined: 2564647  Rows_affected: 0

The query is fast when using FORCE INDEX (PRIMARY).

2307 rows in set (0.06 sec)

Thank you very much for your bug report.

However, we must be able to repeat all that you are reporting. Hence, we need all the tables involved in the queries and the exact queries that produced this slowdown in 5.7.

Thanks in advance.

Will try to reproduce with non-sensitive data

Hi!

Thank you in advance, but we need all data, queries and setup so that we can reproduce the bug properly.

Also, you used FORCE INDEX, but you have to show us exactly which index did you force !!!

We used FORCE INDEX (PRIMARY).

I plan to provide sufficient data and details so you can reproduce.

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".