| Bug #10641 | 1205, 'Lock wait timeout exceeded; try restarting transaction' | ||
|---|---|---|---|
| Submitted: | 14 May 2005 22:02 | Modified: | 13 Jun 2005 6:53 |
| Reporter: | Martin Mokrejs | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 4.1.11 | OS: | Linux (linux-2.6.11.9) |
| Assigned to: | Bugs System | CPU Architecture: | Any |
[14 May 2005 22:02]
Martin Mokrejs
[16 May 2005 6:56]
Jan Lindström
Could you please upload show innodb status printout and show create table for egineered. SELECT clauses could block DELETE clause and cause lock wait. Do you use AUTOCOMMIT = 0 ?
Regards,
JanL
[12 Jun 2005 10:53]
Martin Mokrejs
CREATE TABLE `engineered` (
`engineered_id` bigint(20) unsigned NOT NULL auto_increment,
`IRES_from_gene` varchar(32) default NULL,
`IRES_from_gene_GenBankId` varchar(10) default NULL,
`plasmid_name` varchar(32) default NULL,
`plasmid_sequence_id` bigint(20) unsigned default NULL,
`transcript_integrity` enum('northern-blot','RT-PCR','other','NOT TESTED') default NULL,
`IRES_origin` enum('genomic','mitochondrial','plastidal','plasmidal','viral','engineered') default NULL,
`promoter_name` varchar(32) default NULL,
`organism_id` bigint(20) unsigned default NULL,
`version` int(1) unsigned default '0',
`nucleic_acid_id` bigint(20) unsigned default NULL,
PRIMARY KEY (`engineered_id`),
KEY `plasmid_name` (`plasmid_name`),
KEY `plasmid_sequence_id` (`plasmid_sequence_id`),
KEY `IRES_from_gene` (`IRES_from_gene`),
KEY `IRES_from_gene_GenBankId` (`IRES_from_gene_GenBankId`),
KEY `transcript_integrity` (`transcript_integrity`),
KEY `promoter_name` (`promoter_name`),
KEY `organism_id` (`organism_id`),
KEY `nucleic_acid_id` (`nucleic_acid_id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
[12 Jun 2005 10:54]
Martin Mokrejs
Yes, we use autocommit=0.
[12 Jun 2005 22:17]
Martin Mokrejs
mysql> show innodb status;
=====================================
050613 0:13:56 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 6 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 10, signal count 10
Mutex spin waits 53, rounds 1040, OS waits 1
RW-shared spins 30, OS waits 7; RW-excl spins 4, OS waits 2
------------
TRANSACTIONS
------------
Trx id counter 0 172272
Purge done for trx's n:o < 0 172254 undo n:o < 0 1
History list length 1
Total number of lock structs in row lock hash table 1
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 2689, OS thread id 397323
MySQL thread id 89, query id 5364 localhost 127.0.0.1 root
show innodb status
---TRANSACTION 0 172271, not started, process no 2676, OS thread id 393235
MySQL thread id 88, query id 5363 localhost 127.0.0.1 test
---TRANSACTION 0 172270, ACTIVE 190 sec, process no 2582, OS thread id 389137
MySQL thread id 87, query id 5316 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172271, sees < 0 172246
---TRANSACTION 0 172269, ACTIVE 301 sec, process no 2467, OS thread id 385039
2 lock struct(s), heap size 320, undo log entries 2
MySQL thread id 86, query id 5313 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172270, sees < 0 172246
---TRANSACTION 0 172259, ACTIVE 848 sec, process no 2114, OS thread id 352274
MySQL thread id 78, query id 4909 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172260, sees < 0 172246
---TRANSACTION 0 172252, ACTIVE 1261 sec, process no 1790, OS thread id 335888
MySQL thread id 74, query id 4755 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172253, sees < 0 172246
---TRANSACTION 0 172250, ACTIVE 1709 sec, process no 1580, OS thread id 327690
MySQL thread id 72, query id 4732 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172251, sees < 0 172246
---TRANSACTION 0 172249, ACTIVE 1963 sec, process no 1471, OS thread id 323598
MySQL thread id 71, query id 4713 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172250, sees < 0 172245
---TRANSACTION 0 172248, ACTIVE 2070 sec, process no 1364, OS thread id 319501
MySQL thread id 70, query id 4693 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172249, sees < 0 172245
---TRANSACTION 0 172246, ACTIVE 2145 sec, process no 1355, OS thread id 311308
MySQL thread id 68, query id 4611 localhost 127.0.0.1 test
Trx read view will not see trx with id >= 0 172247, sees < 0 172245
--------
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
380 OS file reads, 2748 OS file writes, 2636 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, is empty
Ibuf for space 0: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 138401, used cells 896, node heap has 2 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 316516759
Log flushed up to 0 316516759
Last checkpoint at 0 316516759
0 pending log writes, 0 pending chkp writes
2590 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 43835498; in additional pool allocated 1048576
Buffer pool size 2048
Free buffers 1422
Database pages 624
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 526, created 98, written 1432
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. 17601, id 28680, state: waiting for server activity
Number of rows inserted 2279, updated 1, deleted 2, read 16605
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
mysql> show processlist;
+----+------+-----------------+------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+------+---------+------+-------+------------------+
| 68 | test | localhost:37373 | test | Sleep | 2151 | | NULL |
| 70 | test | localhost:37379 | test | Sleep | 2076 | | NULL |
| 71 | test | localhost:37381 | test | Sleep | 1968 | | NULL |
| 72 | test | localhost:49036 | test | Sleep | 1715 | | NULL |
| 74 | test | localhost:49832 | test | Sleep | 1266 | | NULL |
| 78 | test | localhost:46378 | test | Sleep | 853 | | NULL |
| 86 | test | localhost:52036 | test | Sleep | 306 | | NULL |
| 87 | test | localhost:52040 | test | Sleep | 196 | | NULL |
| 88 | test | localhost:52042 | test | Sleep | 124 | | NULL |
| 89 | root | localhost:52045 | test | Query | 0 | NULL | show processlist |
+----+------+-----------------+------+---------+------+-------+------------------+
10 rows in set (0.00 sec)
mysql>
The very last transaction which I've noticed that waits was:
050613 0:11:05 88 Connect test@localhost on test
88 Query SET AUTOCOMMIT=0
88 Query SET AUTOCOMMIT=0
88 Query SELECT user_id, user_pwd, user_group FROM submitter WHERE login = 'mokrejsm'
88 Query SELECT login, first_name, last_name, user_id, email FROM submitter WHERE user_id = 5
88 Query SELECT login, first_name, last_name, user_id, email FROM submitter WHERE user_id = 5
88 Query SELECT reviewer_id, reviewer_name FROM reviewers WHERE reviewer_id = 2
88 Query SELECT login, first_name, last_name, user_id, email FROM submitter WHERE user_id = 2
88 Query SELECT login, first_name, last_name, user_id, email FROM submitter WHERE user_id = 2
88 Query SELECT reviewer_id, reviewer_name FROM reviewers WHERE reviewer_id = 2
88 Query SELECT remarks_id FROM remarks WHERE remark='Results indicate that translation mostly occu
rs at AUG2 in the wild-type ERBV IRES but may initiate at AUG3 in the absence of
AUG2 or further downstream in the absence of both AUG2 and AUG3.'
88 Query SELECT count(*) FROM nucleic_acid WHERE remarks_id=38 AND nucleic_acid_id!=47
88 Query SELECT count(*) FROM protein_interaction WHERE remarks_id=38
88 Query SELECT count(*) FROM ss_experiments WHERE remarks_id=38
88 Query SELECT count(*) FROM ires_experiments WHERE remarks_id=38
88 Query SELECT count(*) FROM ss_predictions WHERE remarks_id=38
88 Query SELECT count(*) FROM rRNA_complementarity WHERE remarks_id=38
88 Query SELECT count(*) FROM translation WHERE remarks_id=38
88 Query SELECT count(*) FROM commercial_vector WHERE remarks_id=38
88 Query INSERT INTO remarks (remark) VALUES ('Results indicate that translation mostly occurs at A
UG2 in the wild-type ERBV IRES but may initiate at AUG3 in the absence of
AUG2 or further downstream in the absence of both AUG2 and AUG3.')
88 Query DELETE FROM remarks WHERE remarks_id=38
[DELETE now waits]
[12 Jun 2005 22:25]
Martin Mokrejs
It seems thread 86 caused the problem. My program died so the thread did not commit any changes but the connection is not closed by mysql-python automatically. :(
All other threads you saw in previous comment also not closed, but did only SELECTs (with the exception of thread 88 which tried to do DELETE too). I'm just starting to think this is not a bug in mysql. ;)
050613 0:08:55 86 Connect test@localhost on test
86 Query SET AUTOCOMMIT=0
86 Query SET AUTOCOMMIT=0
86 Query INSERT INTO remarks (remark) VALUES ('Results indicate that translation mostly occurs at A
UG2 in the wild-type ERBV IRES but may initiate at AUG3 in the absence of
AUG2 or further downstream in the absence of both AUG2 and AUG3.')
86 Query DELETE FROM remarks WHERE remarks_id=38
86 Query SELECT organism_id FROM organism WHERE GenBankTaxonomyId=47001 AND organism='Equine rhinit
is B virus 1' AND strain_or_cell_line='1436/71'
86 Query SELECT cistron_id FROM cistron WHERE base_range='904-8664' AND description='Equine Rhinovi
rus type 2 polyprotein.' AND function IS NULL AND gene_name='ERBV_1'
86 Query SELECT mapp_cistron_id FROM mapp_cistron WHERE cistron_1_id IS NULL AND cistron_2_id IS NU
LL AND cistron_3_id IS NULL AND cistron_4_id IS NULL AND cistron_5_id IS NULL
86 Query SELECT count(*) FROM nucleic_acid WHERE mapp_cistron_id=21 AND nucleic_acid_id!=47
[13 Jun 2005 6:53]
Jan Lindström
Thank you for your bug report but I think your problem is not a bug. Lock waits are expected behavior when you have concurrency. If you have a SELECT or DELETE uncommitted it will hold locks until a commit. Any subsequent SELECT or DELETE requesting the same row has to wait release of this lock. Thus if your program dies and mysql-python does not rollback changes automatically locks requested by the transaction will be hold and might cause lock waits (commit is not possible because transactions must be atomic). If you have a lock wait you can rollback all the changes and reissue the transaction.
[13 Aug 2008 11:57]
Bart Verwilst
I am encountering the same issue at my replication setup here ( mysql 5.0.51a ). When you issue statements like this : SET AUTOCOMMIT = 0; UPDATE .... UPDATE .... <snip> COMMIT; And you disconnect the client ( ip failover, ... ) after the autocommit was set to 0, but before the commit statement is reached, the transaction hangs there indefinitely. When the SQL thread for the replication want to write the updates ( that are now handled on the second mysql server ), it wait for the locks to be released, and fails 10 times after 50 seconds each, causing mysql replication to halt. IMO this is not a "feature" as you suggested in the previous comment, since there seems to be no way to stop the transaction other than restarting the mysql server or killing the connection of the transaction ( with kill connection xxx ). Or am i missing something here? Kind regards, Bart Verwilst
