MySQL Bugs: #46759: Dependent subquery locks in 5.1 when it did not lock in 5.0

Bug #46759	Dependent subquery locks in 5.1 when it did not lock in 5.0
Submitted:	17 Aug 2009 14:45	Modified:	30 Jan 2010 8:31
Reporter:	Sheeri Cabral (Candidate Quality Contributor)	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.1.35	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	qc, solaris, subquery, transaction

Description:
A SELECT query with a dependent subquery in a transaction causes locking.  An equivalent JOIN query does not cause the same locking.  The locking has been confirmed on MySQL 5.1.35, and it is confirmed that the locking does *not* occur on MySQL 5.0.74.

SELECT col2 FROM tbl1 a JOIN tbl2 b ON a.col1=b.col2;
is equivalent to
SELECT col1 FROM tbl1 WHERE (col1 IN (SELECT col2 FROM tbl2));

But the former does not cause locking, and the latter does.

How to repeat:
create table if not exists tbl1 (col1 int);       
create table if not exists tbl2 (col2 int);
insert into tbl1 (col1) VALUES (0),(1),(3),(5),(7),(8),(10);
insert into tbl2 (col2) VALUES (0),(1),(2),(4),(6),(8),(10);

Setting prompts:
(machine 1)
mysql> prompt t1> 
PROMPT set to 't1> '
t1> 

(machine 2)
mysql> prompt t2>  
PROMPT set to 't2> '
t2> 

---------------------------------------------------------------------
-- first test to see if the JOIN locks or not -- expected not to lock
t1> start transaction;
Query OK, 0 rows affected (0.00 sec)

t1> SELECT col2 FROM tbl1 a JOIN tbl2 b ON a.col1=b.col2;
+------+
| col2 |
+------+
|    0 | 
|    1 | 
|    8 | 
|   10 | 
+------+
4 rows in set (0.00 sec)

mysql> prompt t2>  
PROMPT set to 't2> '
t2> start transaction;
Query OK, 0 rows affected (0.00 sec)

t2> update tbl2 SET col2=5 WHERE col2=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

-- Ok, this happens right away, as expected.
---------------------------------------------------------------------
-- now test to see if the subquery locks or not -- expected to lock

t2> rollback;
Query OK, 0 rows affected (0.00 sec)

t1> start transaction;
Query OK, 0 rows affected (0.00 sec)

t1> SELECT col1 FROM tbl1 WHERE (col1 IN (SELECT col2 FROM tbl2));
+------+
| col1 |
+------+
|    0 | 
|    1 | 
|    8 | 
|   10 | 
+------+
4 rows in set (0.00 sec)

t2> start transaction;
Query OK, 0 rows affected (0.00 sec)

t2> update tbl2 SET col2=5 WHERE col2=1;

and this hangs.

When tested on:
5.0.74-enterprise-gpl-log
This locking did not occur for *either* the JOIN or the dependent subquery.

Thank you for the report.

I can not repeat described behavior. Please send us output of SHOW ENGINE INNODB STATUS \G during hang and indicate which transaction isolation mode you are using.

mysql> show variables like '%tx_%';
+---------------+-----------------+
| Variable_name | Value |
+---------------+-----------------+
| tx_isolation | REPEATABLE-READ |
+---------------+-----------------+
1 row in set (0.00 sec)

As for the SHOW ENGINE INNODB STATUS:
t1> start transaction;
Query OK, 0 rows affected (0.00 sec)

t1> SELECT col1 FROM tbl1 WHERE (col1 IN (SELECT col2 FROM tbl2));
+------+
| col1 |
+------+
|    0 | 
|    1 | 
|    8 | 
|   10 | 
+------+
4 rows in set (0.00 sec)

t2> start transaction;
Query OK, 0 rows affected (0.00 sec)

t2> update tbl2 SET col2=5 WHERE col2=1;
(hangs here)

t1> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
090817 18:27:40 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2658774, signal count 2654936
Mutex spin waits 0, rounds 15183675, OS waits 471031
RW-shared spins 4112999, OS waits 2015503; RW-excl spins 219544, OS waits 142372
------------
TRANSACTIONS
------------
Trx id counter 0 780652460
Purge done for trx's n:o < 0 780652458 undo n:o < 0 0
History list length 7
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 780652435, not started, OS thread id 34
MySQL thread id 24379, query id 87913060 Has read all relay log; waiting for the slave I/O thread to update it
---TRANSACTION 0 780652459, ACTIVE 8 sec, OS thread id 23 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 33876, query id 87913564 localhost root Updating
update tbl2 SET col2=5 WHERE col2=1
------- TRX HAS BEEN WAITING 8 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6752 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`tbl2` trx id 0 780652459 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000005114b41; asc     KA;; 1: len 6; hex 00002e818b2e; asc   .  .;; 2: len 7; hex 80000000360110; asc     6  ;; 3: len 4; hex 80000000; asc     ;;

------------------
---TRANSACTION 0 780652458, ACTIVE 11 sec, OS thread id 16
2 lock struct(s), heap size 368, 8 row lock(s)
MySQL thread id 33875, query id 87913565 localhost root
show engine innodb status
Trx read view will not see trx with id >= 0 780652459, sees < 0 780652459
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
4303035 OS file reads, 49470448 OS file writes, 40587073 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.31 writes/s, 0.29 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 4428, seg size 4430,
4147303 inserts, 4147303 merged recs, 1996433 merges
Hash table size 10624987, node heap has 3528 buffer(s)
0.00 hash searches/s, 0.03 non-hash searches/s
---
LOG
---
Log sequence number 607 3037868902
Log flushed up to   607 3037868902
Last checkpoint at  607 3037868902
0 pending log writes, 0 pending chkp writes
37530400 log i/o's done, 0.11 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 5860053798; in additional pool allocated 16850688
Dictionary memory allocated 1602248
Buffer pool size   327680
Free buffers       0
Database pages     324152
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 9449042, created 356761, written 13319542
0.00 reads/s, 0.00 creates/s, 0.14 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread id 9, state: waiting for server activity
Number of rows inserted 40224438, updated 27227009, deleted 14333768, read 884126652
0.00 inserts/s, 0.03 updates/s, 0.00 deletes/s, 1.46 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

Just two questions:

Are you using InnoDB or something different?

Are you using plain MySQL server or do you have a replication setup?

This is a slave server, though it has "replicate-do-db" set to one database (not test and not mysql).  

The tables are InnoDB:

mysql> select * from information_schema.tables where table_schema='test'\G
*************************** 1. row ***************************
  TABLE_CATALOG: NULL
   TABLE_SCHEMA: test
     TABLE_NAME: tbl1
     TABLE_TYPE: BASE TABLE
         ENGINE: InnoDB
        VERSION: 10
     ROW_FORMAT: Compact
     TABLE_ROWS: 7
 AVG_ROW_LENGTH: 2340
    DATA_LENGTH: 16384
MAX_DATA_LENGTH: 0
   INDEX_LENGTH: 0
      DATA_FREE: 0
 AUTO_INCREMENT: NULL
    CREATE_TIME: 2009-08-17 14:36:09
    UPDATE_TIME: NULL
     CHECK_TIME: NULL
TABLE_COLLATION: latin1_swedish_ci
       CHECKSUM: NULL
 CREATE_OPTIONS: 
  TABLE_COMMENT: 
*************************** 2. row ***************************
  TABLE_CATALOG: NULL
   TABLE_SCHEMA: test
     TABLE_NAME: tbl2
     TABLE_TYPE: BASE TABLE
         ENGINE: InnoDB
        VERSION: 10
     ROW_FORMAT: Compact
     TABLE_ROWS: 7
 AVG_ROW_LENGTH: 2340
    DATA_LENGTH: 16384
MAX_DATA_LENGTH: 0
   INDEX_LENGTH: 0
      DATA_FREE: 0
 AUTO_INCREMENT: NULL
    CREATE_TIME: 2009-08-17 14:37:21
    UPDATE_TIME: NULL
     CHECK_TIME: NULL
TABLE_COLLATION: latin1_swedish_ci
       CHECKSUM: NULL
 CREATE_OPTIONS: 
  TABLE_COMMENT: 
2 rows in set (0.00 sec)

test case for the testsuite

Attachment: bug46759.test (application/octet-stream, text), 671 bytes.

Thank you for the feedback.

I can not repeat described behavior on OpenSolaris as well. Please try with current version 5.1.37 and inform us if problem still exists.

Test case uploaded contains error and of course hangs. Real test was as you described in the initial description.

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

I can replicate this bug on 5.1.39, using the test case shown in the bug with one change, adding type=InnoDB to the create table statements:

  create table if not exists tbl1 (col1 int) type=InnoDB;       
  create table if not exists tbl2 (col2 int) type=InnoDB;

I've found that it only occurs when bin-logging is on and binlog-format is STATEMENT or MIXED.  ROW doesn't trigger the problem.

Also, I'm running MySQL on Linux (Fedora Core 11 and Centos 5.3) not Solaris.

making sure the status is changed to "open" with the recent comment of the bug on 5.1.39.

originally found on 

SunOS 5.10 Generic_138889-02 i86pc i386 i86pc

but the 5.1.39 example ran on linux, so I'm changing the OS to "any"

I can repeat this bug on 5.1.39 and freebsd.

Changed binlog_format to ROW fixes the issue.

Thank you for the feedback.

Please also send us your configuration file.

looks related to bug 46947

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