Hello List,
I discovered an unusual problem with the way Innodb handles the AUTO_INC lock
with a full table lock. I was wondering if this is a known issue, or I'm doing
something completely wrong. I'm working with MYSQL Server version:
5.0.42-debug-log on Gentoo Linux.
So lets say I have this table:
CREATE TABLE `quicktable` (
`x` int(11) NOT NULL auto_increment,
`quicktext` varchar(50) default NULL,
PRIMARY KEY (`x`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
Several connections are inserting concurrently to the table with normal single
statements such as:
INSERT INTO quicktable (quicktext) VALUES ('Bob 25 item 5');
The value inserted into quicktable changes for every insert to indicate which
connection and which insert its doing
Now in a unique connection is locking the table using the INNODB suggested
method:
SET AUTOCOMMIT = 0;
LOCK TABLES quicktable WRITE;
For demonstration purposes this thread sleeps for a second to simulate
processing that might be going on in the application.
After 1 Second:
COMMIT;
UNLOCK TABLES;
SET AUTOCOMMIT =1;
The result is a dead lock where all queries wait until one of the INSERT's
times out then the LOCK statement manages to get the table lock. But it happens
repeatedly with as few as two connections sending inserts. The server can
handle many many more concurrent inserts if the lock is removed , with out
resulting in any locks.
Here is the output of show processlist:
SHOW PROCESSLIST;
+------+------+-----------+------------+---------+------+--------+--------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info
|
+------+------+-----------+------------+---------+------+--------+--------------------------------------------------------+
| 1470 | bob | localhost | test | Query | 19 | update | INSERT INTO
quicktable (quicktext) VALUES ('Bob 26816 item 5') |
| 1471 | bob | localhost | test | Query | 19 | Locked | INSERT INTO
quicktable (quicktext) VALUES ('Bob 6817 item 2') |
| 1472 | bob | localhost | test | Query | 19 | Locked | LOCK TABLES
quicktable WRITE |
+------+------+-----------+------------+---------+------+--------+------------------------------------------------------+
SHOW INNODB STATUS:
=====================================
071002 16:51:55 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 9 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 91, signal count 91
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 170, OS waits 85; RW-excl spins 7, OS waits 6
------------------------
LATEST DETECTED DEADLOCK
------------------------
071002 16:51:37
*** (1) TRANSACTION:
TRANSACTION 0 26382727, ACTIVE 0 sec, process no 6820, OS thread id 24264721
setting table lock
mysql tables in use 1, locked 0
LOCK WAIT 1 lock struct(s), heap size 320
MySQL thread id 1472, query id 24493 localhost bob System lock
LOCK TABLES quicktable WRITE
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test/quicktable` trx id 0 26382727 lock mode X waiting
*** (2) TRANSACTION:
TRANSACTION 0 26382726, ACTIVE 0 sec, process no 6819, OS thread id 24248336
inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
2 lock struct(s), heap size 320
MySQL thread id 1471, query id 24483 localhost bob update
INSERT INTO quicktable (quicktext) VALUES ('Bob 6817 item 37')
*** (2) HOLDS THE LOCK(S):
TABLE LOCK table `test/quicktable` trx id 0 26382726 lock mode AUTO-INC
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test/quicktable` trx id 0 26382726 lock mode IX waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 0 26382734
Purge done for trx's n:o < 0 26382636 undo n:o < 0 0
History list length 39
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 26382731, not started, process no 6818, OS thread id 24231951
mysql tables in use 1, locked 1
MySQL thread id 1470, query id 24519 localhost bob Table lock
INSERT INTO quicktable (quicktext) VALUES (' Bob 6816 item 38')
---TRANSACTION 0 0, not started, process no 3631, OS thread id 17858573
MySQL thread id 1081, query id 7444 localhost bob
---TRANSACTION 0 26375280, not started, process no 2153, OS thread id 16531468
MySQL thread id 1000, query id 24536 localhost bob
show innodb status
---TRANSACTION 0 0, not started, process no 1894, OS thread id 16318475
MySQL thread id 987, query id 1621 localhost bob
---TRANSACTION 0 26382733, ACTIVE 17 sec, process no 6819, OS thread id
24248336 setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 1 lock struct(s), heap size 320
MySQL thread id 1471, query id 24507 localhost bob update
INSERT INTO quicktable (quicktext) VALUES ('Bob 6817 item 38')
------- TRX HAS BEEN WAITING 17 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test/quicktable` trx id 0 26382733 lock mode AUTO-INC waiting
------------------
---TRANSACTION 0 26382732, ACTIVE 17 sec, process no 6820, OS thread id 24264721
mysql tables in use 1, locked 1
1 lock struct(s), heap size 320
MySQL thread id 1472, query id 24517 localhost bob Table lock
LOCK TABLES quicktable 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
754 OS file reads, 14786 OS file writes, 14479 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.56 writes/s, 0.33 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 5, seg size 7,
2 inserts, 2 merged recs, 1 merges
Hash table size 69257, used cells 491, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 3746566754
Log flushed up to 0 3746566754
Last checkpoint at 0 3746566754
0 pending log writes, 0 pending chkp writes
14298 log i/o's done, 0.11 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 36830648; in additional pool allocated 2097152
Buffer pool size 1024
Free buffers 125
Database pages 897
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 876, created 21, written 450
0.00 reads/s, 0.00 creates/s, 0.33 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 31444, id 131081, state: waiting for server activity
Number of rows inserted 7054, updated 0, deleted 126, read 589
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
Does any one know whats going on? Is this expected behavior?
Thanks in advance,
William
____________________________________________________________________________________
Catch up on fall's hot new shows on Yahoo! TV. Watch previews, get listings,
and more!
http://tv.yahoo.com/collections/3658
