MySQL Bugs: #67615: Massive conccurent inserts and lock wait timeout

Bug #67615	Massive conccurent inserts and lock wait timeout
Submitted:	16 Nov 2012 16:21	Modified:	26 Jan 2018 16:20
Reporter:	CHARVET Vincent	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.5.28	OS:	Linux (6.2)
Assigned to:	Matthew Lord	CPU Architecture:	Any
Tags:	conccurent inserts, lock wait timeout

Description:
Hi,

I have a problem with conccurent inserts in an INNODB table with a foreign key. 

here are the TABLE creation orders : 

------------------------------------------------------------------------------------
create table PARENTS_AUTOINC(
idParent INT NOT NULL AUTO_INCREMENT, 
nom varchar(25), 
primary key (idParent) );

create table ENFANTS_AUTOINC(
idEnfant INT NOT NULL AUTO_INCREMENT, 
idParent int, nom varchar(25), 
primary key (idEnfant), 
constraint CEPARAI0201 foreign key (idParent) references PARENTS_AUTOINC(idParent));
------------------------------------------------------------------------------------

My java program is inserting lines in the two tables using one transaction ( 2 000 000 lines for the PARENT table and 6 000 000 for the child table)
I run 6 of this java program in the same time, so there are six long transactions.

Few minutes later 4 or more programs fail with the followingmessage :

Exception in thread "main" java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction

Looking inside Mysql during the execution shows : 

------------
TRANSACTIONS
------------
Trx id counter 5E544D1
Purge done for trx's n:o < 5E544AB undo n:o < 0
History list length 237
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 117, OS thread handle 0x7f9eb085a700, query id 574380345 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION 0, not started
MySQL thread id 51, OS thread handle 0x7f9eb07d8700, query id 234903278 10.2.55.208 sa701
---TRANSACTION 5E544D0, ACTIVE 80 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 291 lock struct(s), heap size 47544, 3467 row lock(s), undo log entries 13825
MySQL thread id 116, OS thread handle 0x7f9eb099f700, query id 573167514 localhost 127.0.0.1 root update
insert into PARENTS_AUTOINC values (null ,'MAMAN_1729')
------- TRX HAS BEEN WAITING 69 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 338511 n bits 520 index `PRIMARY` of table `ysa701`.`PARENTS_AUTOINC` trx id 5E544D0 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

------------------
---TRANSACTION 5E544CF, ACTIVE 80 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2251 lock struct(s), heap size 260536, 36728 row lock(s), undo log entries 146544
MySQL thread id 115, OS thread handle 0x7f9eb0404700, query id 573694836 localhost 127.0.0.1 root update
insert into PARENTS_AUTOINC values (null ,'PAPA_18319')
------- TRX HAS BEEN WAITING 38 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 337274 n bits 504 index `PRIMARY` of table `ysa701`.`PARENTS_AUTOINC` trx id 5E544CF lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

------------------
---TRANSACTION 5E544CE, ACTIVE 80 sec inserting
mysql tables in use 1, locked 1
5019 lock struct(s), heap size 571832, 111112 row lock(s), undo log entries 443519
MySQL thread id 114, OS thread handle 0x7f9eb08dc700, query id 574380346 localhost 127.0.0.1 root update
insert into ENFANTS_AUTOINC values (null ,12338499,'ENFANT_55440_3')
---TRANSACTION 5E544CD, ACTIVE 80 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3069 lock struct(s), heap size 358840, 57581 row lock(s), undo log entries 229833
MySQL thread id 113, OS thread handle 0x7f9eb091d700, query id 573901916 localhost 127.0.0.1 root update
insert into PARENTS_AUTOINC values (null ,'MAMAN_28730')
------- TRX HAS BEEN WAITING 26 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 335090 n bits 504 index `PRIMARY` of table `ysa701`.`PARENTS_AUTOINC` trx id 5E544CD lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

------------------
---TRANSACTION 5E544CC, ACTIVE 81 sec inserting
mysql tables in use 1, locked 1
5121 lock struct(s), heap size 588216, 112956 row lock(s), undo log entries 450730
MySQL thread id 112, OS thread handle 0x7f9eb06d4700, query id 574380343 localhost 127.0.0.1 root update
insert into ENFANTS_AUTOINC values (null ,12338500,'ENFANT_56342_1')
---TRANSACTION 5E544CB, ACTIVE 81 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 290 lock struct(s), heap size 47544, 3618 row lock(s), undo log entries 14425
MySQL thread id 111, OS thread handle 0x7f9eb0819700, query id 573167515 localhost 127.0.0.1 root update
insert into PARENTS_AUTOINC values (null ,'MAMAN_1804')
------- TRX HAS BEEN WAITING 69 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 338511 n bits 520 index `PRIMARY` of table `ysa701`.`PARENTS_AUTOINC` trx id 5E544CB lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

mysql>  select * from information_schema.INNODB_LOCKS;

| lock_id            | lock_trx_id | lock_mode | lock_type | lock_table                 | lock_index | lock_space | lock_page | lock_rec | lock_data          

| 5E544D0:0:338511:1 | 5E544D0     | X         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    338511 |        1 | supremum 

pseudo-record |
| 5E544CC:0:338511:1 | 5E544CC     | S         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    338511 |        1 | supremum 

pseudo-record |
| 5E544CF:0:337274:1 | 5E544CF     | X         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    337274 |        1 | supremum 

pseudo-record |
| 5E544CC:0:337274:1 | 5E544CC     | S         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    337274 |        1 | supremum 

pseudo-record |
| 5E544CD:0:335090:1 | 5E544CD     | X         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    335090 |        1 | supremum 

pseudo-record |
| 5E544CE:0:335090:1 | 5E544CE     | S         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    335090 |        1 | supremum 

pseudo-record |
| 5E544CB:0:338511:1 | 5E544CB     | X         | RECORD    | `ysa701`.`PARENTS_AUTOINC` | `PRIMARY`  |          0 |    338511 |        1 | supremum 

pseudo-record |

mysql> select * from information_schema.INNODB_LOCK_WAITS;
+-------------------+--------------------+-----------------+--------------------+
| requesting_trx_id | requested_lock_id  | blocking_trx_id | blocking_lock_id   |
+-------------------+--------------------+-----------------+--------------------+
| 5E544D0           | 5E544D0:0:338511:1 | 5E544CC         | 5E544CC:0:338511:1 |
| 5E544CF           | 5E544CF:0:337274:1 | 5E544CC         | 5E544CC:0:337274:1 |
| 5E544CD           | 5E544CD:0:335090:1 | 5E544CE         | 5E544CE:0:335090:1 |
| 5E544CB           | 5E544CB:0:338511:1 | 5E544CC         | 5E544CC:0:338511:1 |
+-------------------+--------------------+-----------------+--------------------+

The java program is very simple it is just inserting lines in a transaction and commiting after inserting 1 000 000 lines in the parent table.
I tried not to use AUTO-INCREMENT columns for my PK (i used a fonction simulating a sequence with the semaphore get_lock) but the result is the same. 
I can provide the function and the java program if you want.

I read the mysql doc and i understood that tere are no gap lock or next key lock in my case. So i don't understand what is happening. Can you help me ?

Thanks.
Vincent Charvet.

How to repeat:
I can provide you all the source code, i can reproduce it easily on my server.

Hello,

I made a mistake on the second part of my message when telling :
"The java program is very simple it is just inserting lines in a transaction and commiting after inserting 1 000 000 lines in the parent table."

Instead you should read :
"The java program is very simple it is just inserting lines in a transaction and commiting after inserting 2 000 000 lines in the parent table and 6 000 000 in the child table."
The problem is reproduced even with less lines.

This problem is getting very serious for us now ... I hope you can just tell us if it's a bug or not.

This is about S lock set to check foreign keys and insert intention locks. Read http://dev.mysql.com/doc/refman/5.5/en//innodb-locks-set.html about them, and do not run this kind of transactions concurrently :)

Thank you for your feedback.

I read the doc many times and i'd really like to have a clear explanation. May be i missed something important and i want to be sure to understand.

What i saw in the doc : 

	"Prior to inserting the row, a type of gap lock called an insertion intention gap lock is set. This lock signals the intent to insert in such a way that multiple transactions inserting into the same index gap need not wait for each other if they are not inserting at the same position within the gap. Suppose that there are index records with values of 4 and 7. Separate transactions that attempt to insert values of 5 and 6 each lock the gap between 4 and 7 with insert intention locks prior to obtaining the exclusive lock on the inserted row, but do not block each other because the rows are nonconflicting. "

I understand here that i can insert conccurently without problems. The main difference in my case is "the foreign key" that is getting a shared lock (or multiple shared locks ?) on the PARENT table when inserting into the CHILD table :

	"If a FOREIGN KEY constraint is defined on a table, any insert, update, or delete that requires the constraint condition to be checked sets shared record-level locks on the records that it looks at to check the constraint. InnoDB also sets these locks in the case where the constraint fails. "

=> My questions are : 

   1) What are the records that it looks at to check the constraint ? I thought it was only the one referenced by the CHILD line we try to insert ... In my test case i am sure that we don't insert the same ID in the PK. Are we, here, concerned by "next key lock" or "gap lock" ?

   2) Even if we lock many records in shared-lock mode to verify the FK, shouldn't they be freed after the insert when the FK is verified ? Do we have to wait until the end of the transaction ?

   I understand now that the session which is inserting in the PARENT table tries to get a insertion intention lock and cannot get it because of shared locks on PARENT'S record (due to the FK verification) ...

   3) But why all of this happens only after a thousand insertions ? Is it about the "supremum pseudo-record" showed in information_schema.INNODB_LOCKS ?

I made a new test with no java, only SQL inserting in the 2 tables massively via a SQL PROCEDURE : i get the same error. 
But when i try to run the inserts individually in different sessions it does not happen. 
I must misunderstand something, hope you can help me ...

here is the test case i talk about :

	drop table ENFANTS_AUTOINC;
	drop table PARENTS_AUTOINC;
	create table PARENTS_AUTOINC(idParent INT NOT NULL AUTO_INCREMENT, nom varchar(25), primary key (idParent) );
	create table ENFANTS_AUTOINC(idEnfant INT NOT NULL AUTO_INCREMENT, idParent int, nom varchar(25), primary key (idEnfant), constraint CEPARAI0201 foreign key (idParent) references PARENTS_AUTOINC(idParent));
	
	DROP PROCEDURE IF EXISTS chargerTablesAutoinc;
	delimiter //
	CREATE PROCEDURE chargerTablesAutoinc(nb_ligne INT)
	BEGIN
	  SET @compteur = 0;
	  label1: LOOP
		SET @compteur = @compteur + 1;
		IF @compteur < nb_ligne THEN 
		  SET @valeur_papa = concat('PAPA_' , @compteur);
		  SET @valeur_maman= concat('MAMAN_' , @compteur);
		  SET @valeur_enfant1= concat('ENFANT_' , @compteur, '_1');
		  SET @valeur_enfant2= concat('ENFANT_' , @compteur, '_2');
		  SET @valeur_enfant3= concat('ENFANT_' , @compteur, '_3');
		  insert into PARENTS_AUTOINC values (null,  @valeur_papa) ;
		  select LAST_INSERT_ID() into @identifiantPapa;
		  insert into PARENTS_AUTOINC values (null, @valeur_maman);
		  select LAST_INSERT_ID() into @identifiantMaman;
		  select @identifiantPapa, @identifiantMaman;
		  insert into ENFANTS_AUTOINC values (null, @identifiantPapa, @valeur_enfant1);
		  insert into ENFANTS_AUTOINC values (null, @identifiantMaman, @valeur_enfant1);
		  insert into ENFANTS_AUTOINC values (null, @identifiantPapa, @valeur_enfant2);
		  insert into ENFANTS_AUTOINC values (null, @identifiantMaman, @valeur_enfant2);
		  insert into ENFANTS_AUTOINC values (null, @identifiantPapa, @valeur_enfant3);
		  insert into ENFANTS_AUTOINC values (null, @identifiantMaman, @valeur_enfant3);
		  ITERATE label1; 
		END IF;
		LEAVE label1;
	  END LOOP label1;
	END
	//
	delimiter ;

In 3 different sessions i run :

	set autocommit=0;
	call chargerTablesAutoinc (10000);

and i still get the lock wait timeout.

We're sorry, but the bug system is not the appropriate forum for asking help on using MySQL products. Your problem is not the result of a clear bug.

Support on using our products is available both free in our forums at http://forums.mysql.com/ and for a reasonable fee direct from our skilled support engineers at http://www.mysql.com/support/

Thank you for your interest in MySQL.

Hi
Has this problem been resolved? Is it a bug? I am encountering the exact same problem and havent been able to find a solution. Any help would be appreciated.

Hi ravi,

I never had a clear answer about this behaviour. We developped a applicative workaround which consisted in avoiding massive modifications on the same lines in multiple sessions. 

Sorry but i cannot help you more.
Vincent.