Bug #27967 Deadlock found when trying to get lock; try restarting transaction
Submitted: 19 Apr 2007 23:17 Modified: 22 May 2007 14:45
Reporter: Simone Giordano Email Updates:
Status: Not a Bug Impact on me:
None 
Category:Connector / NET Severity:S1 (Critical)
Version:5.0.6 OS:Microsoft Windows
Assigned to: CPU Architecture:Any

[19 Apr 2007 23:17] Simone Giordano
Description:
"Deadlock found when trying to get lock; try restarting transaction"

This exception is throwed up in this case:

 - INNODB table
 - autoincrement field
 - two or more concurrent thread 
 - SQL command deleting / inserting via transaction

I'm using ADO.NET Connector 5.0.6 and MySQL version 5.0.27
 
This is the dump of "SHOW INNODB STATUS":

=====================================
070420  1:08:45 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 35 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 6, signal count 6
Mutex spin waits 6, rounds 64, OS waits 1
RW-shared spins 10, OS waits 5; RW-excl spins 1, OS waits 0
------------------------
LATEST DETECTED DEADLOCK
------------------------
070420  1:06:04
*** (1) TRANSACTION:
TRANSACTION 0 20244, ACTIVE 0 sec, OS thread id 1324 inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 320, undo log entries 1
MySQL thread id 11, query id 289 localhost 127.0.0.1 root update
INSERT INTO test (body) VALUES ('19e3727fee3247f5a657c0bd45a4c39f')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 62 n bits 80 index `test1` of table `nuovo/test` trx id 0 20244 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 323463353761353834386239343530353935353963393533306530656239; asc 24c57a5848b945059559c9530e0eb9;...(truncated); 1: len 4; hex 80000009; asc    	;;

*** (2) TRANSACTION:
TRANSACTION 0 20243, ACTIVE 0 sec, OS thread id 568 setting auto-inc lock
mysql tables in use 1, locked 1
5 lock struct(s), heap size 320, undo log entries 11
MySQL thread id 10, query id 290 localhost 127.0.0.1 root update
INSERT INTO test (body) VALUES ('52d1117fe87348ca8a0eeb53f62205fe')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 62 n bits 72 index `test1` of table `nuovo/test` trx id 0 20243 lock_mode X locks gap before rec
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 653865353435616666636537346662666163383937316263326665353936; asc e8e545affce74fbfac8971bc2fe596;...(truncated); 1: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 366438623134363731643438346166366263316236633433363236396164; asc 6d8b14671d484af6bc1b6c436269ad;...(truncated); 1: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 666530353564616235333264343832623961363732303436363635313865; asc fe055dab532d482b9a67204666518e;...(truncated); 1: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 356666313066616537343630346335616131343835363762636432363763; asc 5ff10fae74604c5aa148567bcd267c;...(truncated); 1: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 393437376364383235363564343262646262623335623432326133663731; asc 9477cd82565d42bdbbb35b422a3f71;...(truncated); 1: len 4; hex 80000005; asc     ;;

Record lock, heap no 7 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 323732363631626430353131343532376235373361343566336338633931; asc 272661bd05114527b573a45f3c8c91;...(truncated); 1: len 4; hex 80000006; asc     ;;

Record lock, heap no 8 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 646438653432343063356562343132623932373166356464383438316235; asc dd8e4240c5eb412b9271f5dd8481b5;...(truncated); 1: len 4; hex 80000007; asc     ;;

Record lock, heap no 9 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 633035363961316335626361346264356163316363383030653365626433; asc c0569a1c5bca4bd5ac1cc800e3ebd3;...(truncated); 1: len 4; hex 80000008; asc     ;;

Record lock, heap no 10 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 323463353761353834386239343530353935353963393533306530656239; asc 24c57a5848b945059559c9530e0eb9;...(truncated); 1: len 4; hex 80000009; asc    	;;

Record lock, heap no 11 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 353363636532663332663030343538653963363935613531323831343866; asc 53cce2f32f00458e9c695a5128148f;...(truncated); 1: len 4; hex 8000000a; asc     ;;

Record lock, heap no 12 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 666433633036646639323263343064633965323938313362646237653663; asc fd3c06df922c40dc9e29813bdb7e6c;...(truncated); 1: len 4; hex 8000000b; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `nuovo/test` trx id 0 20243 lock mode AUTO-INC waiting
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 0 20245
Purge done for trx's n:o < 0 20239 undo n:o < 0 0
History list length 11
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, OS thread id 3992
MySQL thread id 12, query id 937 localhost 127.0.0.1 root
SHOW INNODB STATUS
---TRANSACTION 0 0, not started, OS thread id 3872
MySQL thread id 1, query id 932 localhost 127.0.0.1 root
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (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
202 OS file reads, 52 OS file writes, 25 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: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 138401, used cells 0, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 46494467
Log flushed up to   0 46494467
Last checkpoint at  0 46494467
0 pending log writes, 0 pending chkp writes
22 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 40795370; in additional pool allocated 244096
Buffer pool size   2048
Free buffers       1983
Database pages     64
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 64, created 0, written 31
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
1 read views open inside InnoDB
Main thread id 2516, state: waiting for server activity
Number of rows inserted 332, updated 0, deleted 0, read 4
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

How to repeat:
On MySQL:

CREATE TABLE `test` (`id` int(11) NOT NULL auto_increment, `body` varchar(32) default NULL, PRIMARY KEY  (`id`), KEY `test1` (`body`)) ENGINE=InnoDB;

C#:

    private void RunThreads()
    {
      System.Threading.Thread thd1 = new Thread(new ThreadStart(WriteTest));
      System.Threading.Thread thd2 = new Thread(new ThreadStart(WriteTest));

      thd1.Start();
      thd2.Start();
    }

    private void WriteTest()
    {
      string dsn = "Data Source=localhost;User Id=root;Password=XXXXXXXX;Database=nuovo";
      MySql.Data.MySqlClient.MySqlConnection myCon = new MySql.Data.MySqlClient.MySqlConnection(dsn);
      myCon.Open();

      MySql.Data.MySqlClient.MySqlTransaction tran = myCon.BeginTransaction();

      MySql.Data.MySqlClient.MySqlCommand cmd = new MySql.Data.MySqlClient.MySqlCommand();
      cmd.Connection = myCon;
      cmd.Transaction = tran;
      cmd.CommandText = @"DELETE FROM test WHERE body = ?p1;
        INSERT INTO test (body) VALUES (?p1);";

      MySql.Data.MySqlClient.MySqlParameter par = new MySql.Data.MySqlClient.MySqlParameter();
      par.ParameterName = "?p1";
      cmd.Parameters.Add(par);

      for(int i = 0; i < 10000; i++)
      {
        par.Value = Guid.NewGuid().ToString("n");
        cmd.ExecuteNonQuery();
      }

      tran.Commit();
    }
[3 May 2007 9:52] Tonci Grgin
Hi Simone and sorry for the delay in processing. Thanks for your report.
[22 May 2007 14:45] Tonci Grgin
Simone, we checked and rechecked and we don't see the c/NET bug here... Please check on http://dev.mysql.com/doc/refman/5.0/en/innodb-lock-modes.html. This seems to be really a deadlock. I see it more as just a conflict. Txn 1 gets an XLock and that means that txn 2 cannot get an IXLock until txn 1 is done.