Bug #43591 Deadlock on concurrent inserts results in "Lock wait timeout" for other tables
Submitted: 12 Mar 2009 12:00 Modified: 18 Oct 2009 19:25
Reporter: Igor Usoltsev Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Locking Severity:S5 (Performance)
Version:5.0.67 OS:Linux (2.6.27-11 SMP x86_64 GNU/Linux)
Assigned to: CPU Architecture:Any
Tags: Deadlock lock

[12 Mar 2009 12:00] Igor Usoltsev
Description:
We are using Mysql with Web apache/php application.
Periodically the whole web site is hunging with error [Lock wait timeout exceeded; try restarting transaction] on update statistical tables.

How is deadlock on insert in b_iblock_section_element table linked to updates of our statistical tables (b_stat_day,...)?

mysql> SHOW ENGINE INNODB STATUS\G;
LATEST DETECTED DEADLOCK
090311  6:19:59
*** (1) TRANSACTION:
TRANSACTION 0 14541775, ACTIVE 65 sec, process no 6728, OS thread id 1195632976 inserting
mysql tables in use 3, locked 3
LOCK WAIT 19 lock struct(s), heap size 3024, undo log entries 25
MySQL thread id 5071, query id 10282109 192.168.77.77 mkbase Sending data
INSERT INTO b_iblock_section_element(IBLOCK_SECTION_ID, IBLOCK_ELEMENT_ID) SELECT S.ID, E.ID FROM b_iblock_section S, b_iblock_element E WHERE S.IBLOCK_ID=E.IBLOCK_ID 	AND S.ID IN (0,39,38) 	AND E.ID = 236080
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 461340 n bits 608 index `UX_IBLOCK_SECTION_ELEMENT2` of table `mkbase/b_iblock_section_element` trx id 0 14541775 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;;

*** (2) TRANSACTION:
TRANSACTION 0 14548939, ACTIVE 31 sec, process no 6728, OS thread id 1187227984 inserting, thread declared inside InnoDB 500
mysql tables in use 3, locked 3
18 lock struct(s), heap size 3024, undo log entries 27
MySQL thread id 5346, query id 10282118 192.168.77.77 mkbase Sending data
INSERT INTO b_iblock_section_element(IBLOCK_SECTION_ID, IBLOCK_ELEMENT_ID) SELECT S.ID, E.ID FROM b_iblock_section S, b_iblock_element E WHERE S.IBLOCK_ID=E.IBLOCK_ID 	AND S.ID IN (0,31,32) 	AND E.ID = 236082
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 461340 n bits 608 index `UX_IBLOCK_SECTION_ELEMENT2` of table `mkbase/b_iblock_section_element` trx id 0 14548939 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 461340 n bits 608 index `UX_IBLOCK_SECTION_ELEMENT2` of table `mkbase/b_iblock_section_element` trx id 0 14548939 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;;

*** WE ROLL BACK TRANSACTION (1)
TRANSACTIONS
Trx id counter 0 14820079
Purge done for trx's n:o < 0 14820077 undo n:o < 0 0
History list length 18
Total number of lock structs in row lock hash table 16
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 6728, OS thread id 1183025488
MySQL thread id 5418, query id 10532525 localhost root
SHOW ENGINE INNODB STATUS
---TRANSACTION 0 14820053, not started, process no 6728, OS thread id 1264974160
MySQL thread id 5376, query id 10532520 192.168.77.77 mkbase
...
---TRANSACTION 0 14820078, ACTIVE 4 sec, process no 6728, OS thread id 1084111184 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368
MySQL thread id 4976, query id 10532524 192.168.77.77 mkbase Updating
UPDATE b_stat_day SET HITS = HITS + 1, FAVORITES = FAVORITES + 0, HOUR_HIT_14 = HOUR_HIT_14 + 1, WEEKDAY_HIT_3 = WEEKDAY_HIT_3 + 1, MONTH_HIT_3 = MONTH_HIT_3 + 1, HOUR_FAVORITE_14 = HOUR_FAVORITE_14 + 0, WEEKDAY_FAVORITE_3 = WEEKDAY_FAVORITE_3 + 0, MONTH_FAVORITE_3 = MONTH_FAVORITE_3 + 0 WHERE  DATE_STAT = CURRENT_DATE
------- TRX HAS BEEN WAITING 4 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 819218 n bits 192 index `IX_DATE_STAT` of table `mkbase/b_stat_day` trx id 0 14820078 lock_mode X locks rec but not gap waiting
Record lock, heap no 123 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 8fb26b; asc   k;; 1: len 4; hex 8000007a; asc    z;;

TABLE LOCK table `mkbase/b_stat_day` trx id 0 14820078 lock mode IX
RECORD LOCKS space id 0 page no 819218 n bits 192 index `IX_DATE_STAT` of table `mkbase/b_stat_day` trx id 0 14820078 lock_mode X locks rec but not gap waiting
Record lock, heap no 123 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 8fb26b; asc   k;; 1: len 4; hex 8000007a; asc    z;;

---TRANSACTION 0 14820073, ACTIVE 44 sec, process no 6728, OS thread id 1170418000 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368
MySQL thread id 5343, query id 10532514 192.168.77.77 mkbase Updating
UPDATE b_stat_day SET HITS = HITS + 1, FAVORITES = FAVORITES + 0, HOUR_HIT_14 = HOUR_HIT_14 + 1, WEEKDAY_HIT_3 = WEEKDAY_HIT_3 + 1, MONTH_HIT_3 = MONTH_HIT_3 + 1, HOUR_FAVORITE_14 = HOUR_FAVORITE_14 + 0, WEEKDAY_FAVORITE_3 = WEEKDAY_FAVORITE_3 + 0, MONTH_FAVORITE_3 = MONTH_FAVORITE_3 + 0 WHERE  DATE_STAT = CURRENT_DATE
------- TRX HAS BEEN WAITING 44 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 819218 n bits 192 index `IX_DATE_STAT` of table `mkbase/b_stat_day` trx id 0 14820073 lock_mode X locks rec but not gap waiting
Record lock, heap no 123 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 8fb26b; asc   k;; 1: len 4; hex 8000007a; asc    z;;

TABLE LOCK table `mkbase/b_stat_day` trx id 0 14820073 lock mode IX
RECORD LOCKS space id 0 page no 819218 n bits 192 index `IX_DATE_STAT` of table `mkbase/b_stat_day` trx id 0 14820073 lock_mode X locks rec but not gap waiting
Record lock, heap no 123 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 8fb26b; asc   k;; 1: len 4; hex 8000007a; asc    z;;

---TRANSACTION 0 14585003, ACTIVE 1271 sec, process no 6728, OS thread id 1195632976
1 lock struct(s), heap size 368
MySQL thread id 5071, query id 10311470 192.168.77.77 mkbase
TABLE LOCK table `mkbase/b_stat_session` trx id 0 14585003 lock mode IX
---TRANSACTION 0 14584852, ACTIVE 1272 sec, process no 6728, OS thread id 1180924240
23 lock struct(s), heap size 3024, undo log entries 10
MySQL thread id 5091, query id 10429882 192.168.77.77 mkbase
TABLE LOCK table `mkbase/b_stat_session` trx id 0 14584852 lock mode IX
RECORD LOCKS space id 0 page no 1196047 n bits 112 index `PRIMARY` of table `mkbase/b_stat_session` trx id 0 14584852 lock_mode X locks rec but not gap
Record lock, heap no 44 PHYSICAL RECORD: n_fields 36; compact format; info bits 0

TABLE LOCK table `mkbase/b_stat_hit` trx id 0 14584852 lock mode IX
TABLE LOCK table `mkbase/b_stat_day` trx id 0 14584852 lock mode IX
RECORD LOCKS space id 0 page no 819218 n bits 192 index `IX_DATE_STAT` of table `mkbase/b_stat_day` trx id 0 14584852 lock_mode X locks rec but not gap
Record lock, heap no 123 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 3; hex 8fb26b; asc   k;; 1: len 4; hex 8000007a; asc    z;;

RECORD LOCKS space id 0 page no 819230 n bits 80 index `PRIMARY` of table `mkbase/b_stat_day` trx id 0 14584852 lock_mode X locks rec but not gap
Record lock, heap no 8 PHYSICAL RECORD: n_fields 335; compact format; info bits 0

TABLE LOCK table `mkbase/b_stat_day_site` trx id 0 14584852 lock mode IX
RECORD LOCKS space id 0 page no 819233 n bits 280 index `IX_SITE_ID_DATE_STAT` of table `mkbase/b_stat_day_site` trx id 0 14584852 lock_mode X locks rec but not gap
Record lock, heap no 207 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 2; hex 7275; asc ru;; 1: len 3; hex 8fb26b; asc   k;; 2: len 4; hex 800000ce; asc     ;;

RECORD LOCKS space id 0 page no 1130501 n bits 72 index `PRIMARY` of table `mkbase/b_stat_day_site` trx id 0 14584852 lock_mode X locks rec but not gap
Record lock, heap no 4 PHYSICAL RECORD: n_fields 336; compact format; info bits 0

TABLE LOCK table `mkbase/b_stat_guest` trx id 0 14584852 lock mode IX
10 LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS

How to repeat:
No foreign keys are using
Innodb storage engine.
tx_isolation	READ-COMMITTED

show create table b_iblock_section_element
CREATE TABLE `b_iblock_section_element` (
  `IBLOCK_SECTION_ID` int(11) NOT NULL,
  `IBLOCK_ELEMENT_ID` int(11) NOT NULL,
  `ADDITIONAL_PROPERTY_ID` int(18) default NULL,
  UNIQUE KEY `ux_iblock_section_element` (`IBLOCK_SECTION_ID`,`IBLOCK_ELEMENT_ID`,`ADDITIONAL_PROPERTY_ID`),
  KEY `UX_IBLOCK_SECTION_ELEMENT2` (`IBLOCK_ELEMENT_ID`,`IBLOCK_SECTION_ID`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci

Periodically repeatable

Suggested fix:
Unknown
[12 Mar 2009 12:56] Valeriy Kravchuk
Thank you for the problem report. Why do you think DEADLOCK on other table is relevant? You have a long running transaction:

--TRANSACTION 0 14585003, ACTIVE 1271 sec, process no 6728, OS thread id 1195632976

that does NOT wait for anything obvious (at least I do not see it), and holds row locks in the table other transactions are waiting for. 

Do you know why it is not finished for 1200+ seconds?
[12 Mar 2009 14:00] Igor Usoltsev
thanks, Valeriy
May be this is my mistake but I think DEADLOCK on other table is relevant because both these transactions show the same "OS thread id 1195632976":
=====================================
090311  6:43:28 INNODB MONITOR OUTPUT
=====================================
A. LATEST DETECTED DEADLOCK 090311 6:19:59 *** (1) TRANSACTION
TRANSACTION 0 14541775, ACTIVE 65 sec, process no 6728, OS thread id
1195632976 inserting
and
B. ---TRANSACTION 0 14585003, ACTIVE 1271 sec, process no 6728, OS thread id 1195632976

autocommit=on and B-TRANSACTION "does NOT wait for anything obvious" as you wrote.

It's very important for us to define the the source of the locks and avoid this in future.

Sincerely, Igor
[12 Mar 2009 16:28] Igor Usoltsev
And fresh example. "Innodb status" output is in file 10.txt.
innotop shows on DEADLOCK screen:
____________________________ Deadlock Transactions _____________________________
ID   Timestring           User    Host  Victim  Time   Undo  LStrcts  Query Text
188  2009-03-12 18:09:46  mkbase        Yes     00:00    15       18  INSERT INT
164  2009-03-12 18:09:46  mkbase        No      00:00   134       28  INSERT INT

________________________________ Deadlock Locks ________________________________
ID   Waiting  Mode  DB      Table                     Index
188        1  X     mkbase  b_iblock_section_element  UX_IBLOCK_SECTION_ELEMENT2
164        0  X     mkbase  b_iblock_section_element  UX_IBLOCK_SECTION_ELEMENT2
164        1  X     mkbase  b_iblock_section_element  UX_IBLOCK_SECTION_ELEMENT2

and don't shows ID 188 on the LOCK screen at all.
Problem was resolved by "kill 188".

This case seems to me very similar to http://bugs.mysql.com/bug.php?id=43210. We have 3 (almost) simultaneous INSERT's in the same table, then DEADLOCK, and the victim thread, which locking many db objects. Is this correct?

We plan to divide these 3 INSERT's to execute these in different time moments, is this solution reasonable?

Thanks in advance, Igor
[4 Sep 2009 5:52] Sveta Smirnova
Thank you for the feedback.

Yes, this looks very similar to bug #43210. Please check last comment "
[29 Apr 21:47] Paul DuBois " also.

> We plan to divide these 3 INSERT's to execute these in different time moments, is this
solution reasonable?

Yes, this is reasonable. Please update us if it solves the problem which will prove cause is same as in bug #43210
[4 Oct 2009 23:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[5 Oct 2009 18:20] Igor Usoltsev
Yes, it solved the problem.
Thank you
Igor
[6 Oct 2009 7:31] Sveta Smirnova
Thank you for the feedback.

Closed as duplicate of bug #43210
[18 Oct 2009 19:25] Igor Usoltsev
BTW, in our case the problem was successfully solved by changing PHP parameter DBPersistent to FALSE value.
Read full the problem and solution description in my blog http://iusoltsev.wordpress.com/2009/06/21/mysql-deadlock-insert-intention-waiting