| Bug #51140 | Deadlock instead of timeout when inserting the same row from two transactions | ||
|---|---|---|---|
| Submitted: | 12 Feb 2010 12:06 | Modified: | 13 Feb 2010 7:42 |
| Reporter: | Andrew Zhezherun | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.1.31 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | deadlock, innodb | ||
[12 Feb 2010 12:24]
Valeriy Kravchuk
Please, read the manual, http://dev.mysql.com/doc/refman/5.1/en/innodb-locks-set.html, carefully. Doesn't it explain the deadlock situation you get? From concurrency point of view having other UNIQUE index on InnoDB table besides PRIMARY KEY is not the best idea...
[12 Feb 2010 12:57]
Andrew Zhezherun
The only relevant iformation about deadlocks I could find at http://dev.mysql.com/doc/refman/5.1/en/innodb-locks-set.html is the following: "If a duplicate-key error occurs, a shared lock on the duplicate index record is set. This use of a shared lock can result in deadlock should there be multiple sessions trying to insert the same row if another session already has an exclusive lock. This can occur if another session deletes the row." However, in the examples provided in the docs there are three simultaneous transactions, and in my case there are just two, and nobody is deleting any rows from the table. I also don't completely understand the wording "If a duplicate key error occurs". In my example, when transaction 1 tries to insert a record with value = 680, there is no such record in the table, so it should not be a duplicate key error yet? (transaction 2 inserted it but has not committed). If transaction 2 locks this record, then shouldn't transaction 1 just wait until the lock is released? I don't understand where the deadlock is coming from. Why having a unique index is not a good idea? The index ensures consistency of data in my table (it is in fact more complex that this example, but the problem appears even in this simplified table).
[12 Feb 2010 13:09]
Andrew Zhezherun
Also it seems that whether I get a deadlock or not depends on the order of newly inserted values. If I modify my program as follows so that the two processes insert new values in increasing order:
import MySQLdb
import random
import time
from datetime import datetime
if __name__ == "__main__":
db = MySQLdb.connect(db="test", user="user", passwd="password")
value = 0
for i in range(100):
cursor = db.cursor()
value += int(1 + random.random()*5)
print "%s: inserting value %d" % (datetime.today(), value)
cursor.execute("""
INSERT INTO MySQLBug (value) VALUES (%s)
""", (value,))
cursor.execute("""SELECT LAST_INSERT_ID()""")
(id,) = cursor.fetchone()
time.sleep(1 + 0.5*random.random())
db.close()
then there are no deadlocks:
process 1:
bash-3.2$ python mysql_bug_2.py
2010-02-12 13:05:17.184083: inserting value 2
2010-02-12 13:05:18.535083: inserting value 5
2010-02-12 13:05:19.879083: inserting value 7
2010-02-12 13:05:21.223083: inserting value 11
Traceback (most recent call last):
File "mysql_bug_2.py", line 15, in <module>
""", (value,))
File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/cursors.py", line 173, in execute
File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/connections.py", line 36, in defaulterrorhandler
_mysql_exceptions.OperationalError: (1205, 'Lock wait timeout exceeded; try restarting transaction')
process 2:
bash-3.2$ python mysql_bug_2.py
2010-02-12 13:05:15.262221: inserting value 3
2010-02-12 13:05:16.527221: inserting value 4
2010-02-12 13:05:17.678221: inserting value 8
2010-02-12 13:05:18.701221: inserting value 11
2010-02-12 13:05:19.820221: inserting value 14
2010-02-12 13:05:21.148221: inserting value 16
2010-02-12 13:05:22.263221: inserting value 20
...
but a lock timeout as expected.
[12 Feb 2010 13:32]
Andrew Zhezherun
Fixed the title.
[12 Feb 2010 17:10]
Andrew Zhezherun
I could reproduce this problem with just one key as following:
CREATE TABLE MySQLBug2 (
value INT UNSIGNED NOT NULL,
PRIMARY KEY (value)
) ENGINE=InnoDB
Then I run two parallel instances of this program:
import MySQLdb
import random
import time
from datetime import datetime
if __name__ == "__main__":
db = MySQLdb.connect(db="test", user="user", passwd="password")
for i in range(100):
cursor = db.cursor()
value = int(random.random() * 1000)
print "%s: inserting value %d" % (datetime.today(), value)
cursor.execute("""
INSERT INTO MySQLBug2 (value) VALUES (%s)
""", (value,))
time.sleep(1 + 0.5*random.random())
db.close()
and get the following output:
process 1:
bash-3.2$ python mysql_bug_3.py
2010-02-12 17:00:49.796759: inserting value 49
2010-02-12 17:00:50.801759: inserting value 578
2010-02-12 17:00:52.180759: inserting value 114
2010-02-12 17:00:53.651759: inserting value 775
2010-02-12 17:00:54.788759: inserting value 877
2010-02-12 17:00:55.940759: inserting value 467
2010-02-12 17:00:57.083759: inserting value 301
2010-02-12 17:00:58.467759: inserting value 63
2010-02-12 17:00:59.544759: inserting value 640
2010-02-12 17:01:00.840759: inserting value 15
2010-02-12 17:01:02.040759: inserting value 6
2010-02-12 17:01:03.151759: inserting value 152
2010-02-12 17:01:04.536759: inserting value 764
2010-02-12 17:01:06.036759: inserting value 723
2010-02-12 17:01:07.106759: inserting value 20
2010-02-12 17:01:08.456759: inserting value 212
Traceback (most recent call last):
File "mysql_bug_3.py", line 14, in <module>
""", (value,))
File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/cursors.py", line 173, in execute
File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/connections.py", line 36, in defaulterrorhandler
_mysql_exceptions.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')
process 2:
bash-3.2$ python2.6 mysql_bug_3.py
2010-02-12 17:00:47.921771: inserting value 159
2010-02-12 17:00:49.196771: inserting value 615
2010-02-12 17:00:50.407771: inserting value 394
2010-02-12 17:00:51.753771: inserting value 212
2010-02-12 17:00:53.051771: inserting value 179
2010-02-12 17:00:54.194771: inserting value 339
2010-02-12 17:00:55.465771: inserting value 785
2010-02-12 17:00:56.671771: inserting value 53
2010-02-12 17:00:57.770771: inserting value 195
2010-02-12 17:00:59.131771: inserting value 573
2010-02-12 17:01:00.483771: inserting value 498
2010-02-12 17:01:01.540771: inserting value 321
2010-02-12 17:01:02.665771: inserting value 230
2010-02-12 17:01:04.008771: inserting value 611
2010-02-12 17:01:05.299771: inserting value 805
2010-02-12 17:01:06.360771: inserting value 924
2010-02-12 17:01:07.489771: inserting value 15
2010-02-12 17:01:09.780771: inserting value 469
...
Show innodb status reports:
------------------------
LATEST DETECTED DEADLOCK
------------------------
100212 17:01:08
*** (1) TRANSACTION:
TRANSACTION 0 169411944, ACTIVE 20 sec, process no 11616, OS thread id 1164048736 inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 368, 2 row lock(s), undo log entries 16
MySQL thread id 221649, query id 60755581 sneezy 192.168.1.17 user update
INSERT INTO MySQLBug2 (value) VALUES (15)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3864 n bits 120 index `PRIMARY` of table `test`.`MySQLBug2` trx id 0 169411944 lock mode S locks rec but not gap waiting
Record lock, heap no 42 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 4; hex 0000000f; asc ;; 1: len 6; hex 00000a190569; asc i;; 2: len 7; hex 8000000f160185; asc ;;
*** (2) TRANSACTION:
TRANSACTION 0 169411945, ACTIVE 19 sec, process no 11616, OS thread id 1163516256 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
3 lock struct(s), heap size 368, 2 row lock(s), undo log entries 15
MySQL thread id 221650, query id 60755582 sneezy 192.168.1.17 user update
INSERT INTO MySQLBug2 (value) VALUES (212)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 3864 n bits 120 index `PRIMARY` of table `test`.`MySQLBug2` trx id 0 169411945 lock_mode X locks rec but not gap
Record lock, heap no 42 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 4; hex 0000000f; asc ;; 1: len 6; hex 00000a190569; asc i;; 2: len 7; hex 8000000f160185; asc ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 3864 n bits 120 index `PRIMARY` of table `test`.`MySQLBug2` trx id 0 169411945 lock mode S locks rec but not gap waiting
Record lock, heap no 20 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 4; hex 000000d4; asc ;; 1: len 6; hex 00000a190568; asc h;; 2: len 7; hex 80000000370137; asc 7 7;;
*** WE ROLL BACK TRANSACTION (2)
And as before, if I insert values in increasing order, there is no deadlock detected but the transaction waits for a lock to be released.
Am I missing something obvious here?
[12 Feb 2010 17:33]
Valeriy Kravchuk
Your last example is absolutely clear. Let me left only information about insertions of relevant rows, 15 and 212, from your output: bash-3.2$ python mysql_bug_3.py ... 2010-02-12 17:01:00.840759: inserting value 15 ... 2010-02-12 17:01:08.456759: inserting value 212 bash-3.2$ python2.6 mysql_bug_3.py ... 2010-02-12 17:00:51.753771: inserting value 212 ... 2010-02-12 17:01:07.489771: inserting value 15 ... So, your process2 inserted row with value 212 first (17:00:51.753771), then your process1 inserted row with value 15 (17:01:00.840759), then your process2 tried to insert row with value 15 (17:01:07.489771) and was blocked because of lock set on this row by process1. Finally, your process1 tried to insert row with value 212 (17:01:08.456759) and had to be blocked because of lock set on this row by process2, but InnoDB detected correctly that process1 can not be blocked, as this will lead to a deadlock. So, one of transactions was picked up and rolled back... This is a classical "X shape" deadlock - you inserted same rows from different transactions in an opposite order. When order of insertions in two transactions is the same no deadlock happens. Transaction that tried to insert the same row already inserted by another one has to wait for a lock release. There is NO indication of any bug in your examples, sorry. InnoDB works as designed and as described in the manual. Your nice test case, with timestamps, shows this perfectly.
[12 Feb 2010 22:33]
Andrew Zhezherun
Ok, I agree that I didn't study the output of my second example carefully enough before posting it, I am sorry about that. However, my first example (with a unique key) still stands. The obvious deadlock from the second example is not present there.
[13 Feb 2010 7:42]
Valeriy Kravchuk
In your initial example the story is a bit more complicated. But it is still clear. Your process2 inserted value 680 (you have unique index on this column): ... 2010-02-12 11:49:55.474530: inserting value 680 ... Later (at the moment of deadlock) process2 tried to insert value 565. It inserted row itself and X locked it. (But that's not enough to complete insertion, it has to lock gap after 565...) Then your process1 tried to insert value 680 (last action of it): ... 2010-02-12 11:50:03.873026: inserting value 680 As this value is already there, process1 started to wait on S lock on this row. And at this moment process2 tried to lock that gap after 565, and it happened so that it is just before 680, as you inserted the following values (in asc order of values): p2 2010-02-12 11:50:02.245530: inserting value 0 p1 2010-02-12 11:49:54.838026: inserting value 34 p1 2010-02-12 11:50:02.644026: inserting value 43 p1 2010-02-12 11:50:00.099026: inserting value 110 p1 2010-02-12 11:50:01.146026: inserting value 126 p2 2010-02-12 11:49:54.275530: inserting value 139 p1 2010-02-12 11:49:57.576026: inserting value 223 p2 2010-02-12 11:50:04.542530: inserting value 240 p2 2010-02-12 11:49:58.232530: inserting value 343 p1 2010-02-12 11:49:56.173026: inserting value 369 p1 2010-02-12 11:49:58.632026: inserting value 404 p2 2010-02-12 11:49:59.460530: inserting value 415 p2 2010-02-12 11:50:03.474530: inserting value 519 p2 (and later p1) 2010-02-12 11:49:55.474530: inserting value 680 p2 2010-02-12 11:50:00.845530: inserting value 684 p2 2010-02-12 11:49:56.837530: inserting value 744 As you can see from the above, next value after 565 that you are trying to insert is 680! Same "X shape" deadlock happaned, just with locks on other, unique index, and with S lock and gap lock involved. Think about it. No reason to call this a bug. Expected and documented behavior (even if not any obvious). Let's stop discuss InnoDB locking here. There are many forums for this, while bugs database should be used for bug reporting only.
Description: I have a table which multiple processes write to concurrently and I receive deadlocks where I think I should not. My database structure is quite complex, but I was able to narrow down the problem to the following simple test case. The table that I am inserting records to looks like this: CREATE TABLE MySQLBug ( id INT UNSIGNED NOT NULL AUTO_INCREMENT, value INT UNSIGNED NOT NULL, PRIMARY KEY (id), UNIQUE KEY Test_Index (value) ) ENGINE=InnoDB The table is initially empty, and then two processes insert records into this table, each one inside a transaction (auto_commit is set to 0, and no explicit commit() is issued). When one process tries to insert a value already inserted (in a separate transaction) by another process, a deadlock is reported as follows: process 1: bash-3.2$ python mysql_bug.py 2010-02-12 11:49:54.838026: inserting value 34 2010-02-12 11:49:56.173026: inserting value 369 2010-02-12 11:49:57.576026: inserting value 223 2010-02-12 11:49:58.632026: inserting value 404 2010-02-12 11:50:00.099026: inserting value 110 2010-02-12 11:50:01.146026: inserting value 126 2010-02-12 11:50:02.644026: inserting value 43 2010-02-12 11:50:03.873026: inserting value 680 Traceback (most recent call last): File "mysql_bug.py", line 14, in <module> """, (value,)) File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/cursors.py", line 173, in execute File "build/bdist.cygwin-1.7.1-i686/egg/MySQLdb/connections.py", line 36, in defaulterrorhandler _mysql_exceptions.OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction') process 2: bash-3.2$ python mysql_bug.py 2010-02-12 11:49:54.275530: inserting value 139 2010-02-12 11:49:55.474530: inserting value 680 2010-02-12 11:49:56.837530: inserting value 744 2010-02-12 11:49:58.232530: inserting value 343 2010-02-12 11:49:59.460530: inserting value 415 2010-02-12 11:50:00.845530: inserting value 684 2010-02-12 11:50:02.245530: inserting value 0 2010-02-12 11:50:03.474530: inserting value 519 2010-02-12 11:50:04.542530: inserting value 240 ... This is what I got from show innodb status: ------------------------ LATEST DETECTED DEADLOCK ------------------------ 100212 11:50:06 *** (1) TRANSACTION: TRANSACTION 0 169389209, ACTIVE 12 sec, process no 11616, OS thread id 1163516256 inserting mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s), undo log entries 8 MySQL thread id 204435, query id 60677919 sneezy 192.168.1.17 user update INSERT INTO MySQLBug (value) VALUES (680) *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 282 n bits 176 index `Test_Index` of table `test`.`MySQLBug` trx id 0 169389209 lock mode S waiting Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 000002a8; asc ;; 1: len 4; hex 00000e7c; asc |;; *** (2) TRANSACTION: TRANSACTION 0 169389200, ACTIVE 12 sec, process no 11616, OS thread id 1161120096 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 3 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 10 MySQL thread id 204428, query id 60677940 sneezy 192.168.1.17 user update INSERT INTO MySQLBug (value) VALUES (565) *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 282 n bits 176 index `Test_Index` of table `test`.`MySQLBug` trx id 0 169389200 lock_mode X locks rec but not gap Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 000002a8; asc ;; 1: len 4; hex 00000e7c; asc |;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 282 n bits 176 index `Test_Index` of table `qlib_tests`.`MySQLBug` trx id 0 169389200 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 000002a8; asc ;; 1: len 4; hex 00000e7c; asc |;; *** WE ROLL BACK TRANSACTION (1) I expect the first transaction to go through normally and then fail at commit time with a duplicate key error, or at least block until the second transaction does a commit or a rollback and then either continue or report a duplicate key. However, a deadlock in this situation is completely unexpected. How to repeat: I used the following Python program to reproduce this bug: import MySQLdb import random import time from datetime import datetime if __name__ == "__main__": db = MySQLdb.connect(db="test", user="user", passwd="password") for i in range(1,100): cursor = db.cursor() value = int(random.random()*1000) print "%s: inserting value %d" % (datetime.today(), value) cursor.execute(""" INSERT INTO MySQLBug (value) VALUES (%s) """, (value,)) cursor.execute("""SELECT LAST_INSERT_ID()""") (id,) = cursor.fetchone() time.sleep(1 + 0.5*random.random()) db.close()