-none- 2007-10-02 - By Baron Schwartz
Back
Hi William,
William Newton wrote:
> 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?
It sounds to me like the expected behavior if you have AUTOCOMMIT enabled.
http://dev.mysql.com/doc/refman/5.0/en/lock-tables.html
Baron
--
MySQL General Mailing List
For list archives: http://lists.mysql.com/mysql
To unsubscribe: http://lists.mysql.com/mysql?unsub=mysql@(protected)
|
|
