Bug #3894 lock tables ... write works wrong
Submitted: 26 May 2004 5:52 Modified: 31 May 2004 15:47
Reporter: Igor Blagodetelev Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:4.0.20 OS:Linux (RedHat Linux)
Assigned to: Marko Mäkelä CPU Architecture:Any

[26 May 2004 5:52] Igor Blagodetelev
Description:
When two concurent connections lock the same table for write one of connection wait while second connection not call 'UNLOCK TABLES'. That's right, but in the MySQL 4.0.20 queries, which comes after success 'LOCK TABLES ... WRITE' freeze and after timeout ends with error: 'ERROR 1205: Lock wait timeout exceeded; Try restarting transaction'.
mysql> select version();
+----------------+
| version()      |
+----------------+
| 4.0.20-Max-log |
+----------------+
1 row in set (0.02 sec)

[db@develop db]$ cat /proc/version
Linux version 2.4.21-9.0.1.ELsmp (root@sol.ksn.ru) (gcc version 3.2.3 20030502 (Red Hat Linux 3.2.3-24)) #1 SMP Пнд Мар 29 16:27:59 NOVST 2004
[db@develop db]$ cat /etc/redhat-release
Red Hat Enterprise Linux AS release 3 (Taroon Update 2)
[db@develop db]$ rpm -q MySQL-server MySQL-Max
MySQL-server-4.0.20-0
MySQL-Max-4.0.20-0
(RPMs from www.mysql.com)

How to repeat:
Need two concurrent connection for database test: A and B.

A:
mysql> create table table_for_lock_innodb (id int) type=innodb;
Query OK, 0 rows affected (0.03 sec)

mysql> lock tables table_for_lock_innodb write;
Query OK, 0 rows affected (0.00 sec)

B:
mysql> lock tables table_for_lock_innodb write;
===== WAIT UNLOCK =====

A:
mysql> select id from table_for_lock_innodb where id=1;
====== Unknown wait and after lock timeout: ======
ERROR 1205: Lock wait timeout exceeded; Try restarting transaction

B:
====== Still wait for unlock ======

A:
mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

B:
Query OK, 0 rows affected (2 min 34.63 sec)

mysql>

The same test runs on 4.0.18 works successfully.

Suggested fix:
Unknown yet...
[26 May 2004 9:02] Heikki Tuuri
Hi!

I was able to repeat this with the latest 4.0 tree. There is a mysterious IX table lock request that A is waiting for.

Thank you for the bug report.

Heikki

Connection A:

heikki@hundin:~/mysql-4.0prod/client> ./mysql test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 4.0.20-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> create table t(a int) type = innodb;
Query OK, 0 rows affected (0.01 sec)

mysql> insert into t values (1);
Query OK, 1 row affected (0.00 sec)

mysql> lock tables t write;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t;
ERROR 1205: Lock wait timeout exceeded; Try restarting transaction
mysql>

Connection B:

heikki@hundin:~/mysql-4.0prod/client> ./mysql test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3 to server version: 4.0.20-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> lock table t write;

Connection C (for diagnostics):

mysql> show innodb status\G
*************************** 1. row ***************************
Status:
=====================================
040526  9:50:42 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 12, signal count 12
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 24, OS waits 12; RW-excl spins 0, OS waits 0
------------
TRANSACTIONS
------------
Trx id counter 0 774
Purge done for trx's n:o < 0 0 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 25463, OS thread id 163851
MySQL thread id 2, query id 7 localhost heikki
show innodb status
---TRANSACTION 0 773, ACTIVE 13 sec, process no 25437, OS thread id 147466 start
ing index read
mysql tables in use 1, locked 1
LOCK WAIT 1 lock struct(s), heap size 320
MySQL thread id 1, query id 5 localhost heikki Sending data
select * from t
------- TRX HAS BEEN WAITING 13 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test/t` trx id 0 773 lock mode IX waiting
------------------
---TRANSACTION 0 772, ACTIVE 20 sec, process no 25490, OS thread id 180236
mysql tables in use 1, locked 1
1 lock struct(s), heap size 320
MySQL thread id 3, query id 4 localhost heikki Table lock
lock table t write
--------
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
1 OS file reads, 57 OS file writes, 65 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 62383, used cells 0, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 45476
Log flushed up to   0 45476
Last checkpoint at  0 45476
0 pending log writes, 0 pending chkp writes
26 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 37250593; in additional pool allocated 909440
Buffer pool size   960
Free buffers       780
Database pages     179
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 0, created 179, written 205
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
Main thread process no. 25434, id 114696, state: waiting for server activity
Number of rows inserted 1, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.01 sec)

mysql>
[26 May 2004 12:32] Heikki Tuuri
Hi!

I found out why this strange behavior.

1) First, since MySQL has set an exclusive table lock on the table handle, InnoDB thinks that every consistent read should be converted to an X-locking read. That explains why the SELECT tries to set an IX-lock on the table.

2) Since AUTOCOMMIT=1, MySQL runs an implicit commit immediately after the LOCK TABLES command. That commit releases the X-lock on the table set inside InnoDB!

How to fix:

1) Maybe we could set prebuilt->select_lock_type = LOCK_NONE in ha_innobase::start_statement()? No we cannot, since MySQL may run an UPDATE statement protected by that WRITE lock it has on the table. Hmmm... we could set it to LOCK NONE at a SELECT statement that is not a locking read, but to LOCK_X at all other SQL statements? Then the user could run consistent read SELECTs on a table even though he has an X-lock on the table.

2) The second problem is conceptually difficult to solve. MySQL's table locks do not care about trx commits, but inside InnoDB, all locks are released at a commit. I think the current behavior is the most logical. Using table locks in a transactional database is only sensible if autocommit is not on.

...

Workaround for 4.0.20: SET AUTOCOMMIT=0 and do not commit the trx until you also want to release the MySQL table locks. Then it executes like below:

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> lock tables t write;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t;
+------+
| a    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql>

mysqld printout:
Setting SELECT lock type to 5 LOCK_X in ::external_lock
Setting mysql_has_locked TRUE in ::external_lock
Setting table lock in mode 5 on a table
Setting table lock in mode 3 on a table
Found lock mode 5 already on the table, trx id 2821, lock trx id 2821
Testing if lock mode 5 is stronger than 3
Had a stronger lock, no need to set another lock

Regards,

Heikki

heikki@hundin:~/mysql-4.0prod/client> ./mysql test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 4.0.20-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> lock tables t write;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t;
+------+
| a    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql> select * from t;
+------+
| a    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t;
+------+
| a    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql> select * from t;
+------+
| a    |
+------+
|    1 |
+------+
1 row in set (0.00 sec)

mysql>

Version: '4.0.20-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307
Setting SELECT lock type to 0 LOCK_NONE in ::store_lock
Setting SELECT lock type to 5 LOCK_X in ::external_lock
Setting mysql_has_locked TRUE in ::external_lock
Setting table lock in mode 5 on a table
Releasing all locks of a trx
Setting table lock in mode 3 on a table
Releasing all locks of a trx
Setting table lock in mode 3 on a table
Releasing all locks of a trx
Setting table lock in mode 3 on a table
Setting table lock in mode 3 on a table
Found lock mode 3 already on the table, trx id 2819, lock trx id 2819
Testing if lock mode 3 is stronger than 3
Had a stronger lock, no need to set another lock
[31 May 2004 15:47] Marko Mäkelä
Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

Additional info:

ChangeSet@1.1873

The MySQL/InnoDB interface will no longer obtain a lock for consistent reads (such as the SELECT statement of your test case).

Some other problems still remain.  We should implement a variant of LOCK TABLES that is released when the transaction is committed or rolled back.