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
============================
--

---------------------------------------------------------------------
Before posting, please check:
   http://www.mysql.com/manual.php   (the manual)
   http://lists.mysql.com/           (the list archive)

To request this thread, e-mail <[EMAIL PROTECTED]>
To unsubscribe, e-mail <[EMAIL PROTECTED]>
Trouble unsubscribing? Try: http://lists.mysql.com/php/unsubscribe.php

Reply via email to