InnoDB locks disappear

[Wouter Zelle]

My program uses locks to allow for multi-threading (processing 
requests that are stored in the database using more than one thread 
and/or application). The problem is that the locks disappear for 
seemingly no reason at all. The same queries are repeated over and 
over again until the lock just vanishes, so it seems to be a time-out 
or something like that. I've created a log-file of the queries and 
two reports from the innodb_lock_monitor, the one just before the 
lock vanishes and the one after.

I would really appreciate some help,

Wouter Zelle

---Query log
-- Comments:
At the start of the fragment the request is being locked in 
connection #23 (every request is locked in a seperate connection so 
commits won't do harm anyone else). The next query (14:43:13) finds 
all unprocessed requests in the DB (Connection #22 is used for this 
query). The 'For Update'-query tries to lock the request and fails if 
it is already locked (causing my app to move on to the next request). 
Connection #24 is used for this kind of query after 14:43:18. As you 
can see, the two types of requests keep interleaving until I halted 
the app, which was after the request was unlocked.

I've cleaned up the log a bit for easy reading.
---
14:42:42   23 Connect     wouter@localhost on
	   23 Init DB     rosetta
	   23 Query       SHOW VARIABLES
	   23 Query       SET autocommit=0
	   23 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:43:13   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:43:18   24 Connect     wouter@localhost on
	   24 Init DB     rosetta
	   24 Query       SHOW VARIABLES
	   24 Query       SET autocommit=0
	   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:43:43   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:44:12   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:44:33   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:44:53   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:45:18   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:45:24   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:45:42   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:45:54   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:46:23   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
	   22 Query       commit
14:46:41   24 Query       SELECT [t0.columns] FROM REQUEST t0, 
ROSETTA_USER T1 WHERE (t0.EXTERNAL_IDENTIFIER = 'RequestID01' AND 
T1.LOGIN = 'login') AND t0.USER_ID = T1.USER_ID FOR UPDATE
14:47:08   22 Query       SELECT [t0.columns] FROM REQUEST t0 WHERE 
t0.STATUS = 'ReadyForProcessing' ORDER BY t0.CREATION_DATE ASC
14:47:09   22 Query       commit
	   23 Quit
14:47:28    3 Query       DROP TABLE innodb_lock_monitor
---End Query Log

---INNODB MONITOR OUTPUT
-- Comments:
I took out everything but the transactions, since I don't think the 
rest will be of any help. If you need some other info, please ask.
--
---
=====================================
14:47:06 INNODB MONITOR OUTPUT
=====================================
------------
TRANSACTIONS
------------
Trx id counter 0 370112
Purge done for trx's n:o < 0 370096 undo n:o < 0 0
Total number of lock structs in row lock hash table 2
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 370111, not started, OS thread id 1660
MySQL thread id 24, query id 1036 localhost 127.0.0.1 wouter
---TRANSACTION 0 370110, not started, OS thread id 1636
MySQL thread id 22, query id 1035 localhost 127.0.0.1 wouter
---TRANSACTION 0 370099, ACTIVE 264 sec, OS thread id 292
4 lock struct(s), heap size 320
MySQL thread id 23, query id 1015 localhost 127.0.0.1 wouter
TABLE LOCK table rosetta/request trx id 0 370099 lock_mode IX
RECORD LOCKS space id 0 page no 50 n bits 80 table rosetta/request 
index PRIMARY
  trx id 0 370099 lock_mode X
Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 
73757072656d756d00; asc
  supremum.;;
Record lock, heap no 2 RECORD: info bits 0 0: len 8; hex 
80000000000000c5; asc .
.......;; 1:
Record lock, heap no 10 RECORD: info bits 0 0: len 8; hex 80000000000000e8; asc
.......Þ;; 1:
Suppressing further record lock prints for this page
TABLE LOCK table rosetta/rosetta_user trx id 0 370099 lock_mode IX
RECORD LOCKS space id 0 page no 53 n bits 288 table 
rosetta/rosetta_user index P
RIMARY trx id 0 370099 lock_mode X
Record lock, heap no 220 RECORD: info bits 0 0: len 8; hex 
8000000000000d28; asc
  .......(;; 1:
----------------------------
END OF INNODB MONITOR OUTPUT
============================

=====================================
14:47:22 INNODB MONITOR OUTPUT
=====================================
------------
TRANSACTIONS
------------
Trx id counter 0 370113
Purge done for trx's n:o < 0 370096 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 370111, not started, OS thread id 1660
MySQL thread id 24, query id 1036 localhost 127.0.0.1 wouter
---TRANSACTION 0 370112, not started, OS thread id 1636
MySQL thread id 22, query id 1038 localhost 127.0.0.1 wouter
----------------------------
END OF INNODB MONITOR OUTPUT
============================
--