Bug #72407 Unclear Deadlock conditions with delete / update statement.
| Submitted: | 20 Apr 2014 20:47 | Modified: | 24 Apr 2014 17:30 |
|---|---|---|---|
| Reporter: | Shahriyar Rzayev | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: Locking | Severity: | S1 (Critical) |
| Version: | 5.6.10, 5.6.17 | OS: | Linux (Centos 6.5/6.3) |
| Assigned to: | CPU Architecture: | Any |
[21 Apr 2014 17:59]
Sveta Smirnova
Thank you for the report. I assume you run UPDATE and DELETE in parallel in two sessions? Also you don't wait when transaction, running UPDATEs finishes? In this case this is not a bug. Why deadlock happens clearly explained at http://dev.mysql.com/doc/refman/5.6/en/glossary.html#glos_deadlock If you, however, run UPDATE and DELETE in single session (as seen in how-to-repeat instructions) or you ensured that all UPDATEs finished and only then run DELETE in parallel session and see deadlock (not "Lock wait timeout exceeded; try restarting transaction" error) please check with current version 5.6.17 and, if could repeat, reopen the report.
[22 Apr 2014 5:56]
Shahriyar Rzayev
This deadlock issue is on my production installation and the version is 5.6.10 i can test it on 5.6.17 but in fact it will not help me , because i can't do version upgrade now... From this point i installed new servers on Virtualbox for testing purpose...this case is on my test servers. For link you provided, i have already read MySQL Glossary with great interest. The question is about deadlock output which was found in error log.. Locking related information was: For Transaction 1: *** (1) WAITING FOR THIS LOCK TO BE GRANTED: lock_mode X waiting Record lock For Transaction 2: *** (2) HOLDS THE LOCK(S): lock_mode X locks rec but not gap Record lock *** (2) WAITING FOR THIS LOCK TO BE GRANTED: lock_mode X locks gap before rec insert intention waiting Record lock As i search: "lock_mode X locks gap before rec insert intention waiting Record lock" -- is happening while executing insert statements but i did not run any insert statement. And as deadlock monitor stated, The Transaction 1 is DELETE, Transaction 2 is UPDATE. Any explanation for this situation?
[22 Apr 2014 12:51]
Shahriyar Rzayev
Upgraded from MySQL 5.6.10 to 5.6.17 and here is different deadlock detected output with 5 minute interval: ## 1st OUTPUT ## ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2014-04-22 15:46:44 7ff4d00c6700 *** (1) TRANSACTION: TRANSACTION 2700088, ACTIVE 0 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 3 lock struct(s), heap size 1184, 2 row lock(s) MySQL thread id 275430, OS thread handle 0x7ff4d0823700, query id 3949280 85.132.52.203 vesti_user updating DELETE FROM `online` WHERE `time` < 1398164266 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 220 page no 14 n bits 328 index `PRIMARY` of table `vesti_db`.`online` trx id 2700088 lock_mode X locks rec but not gap waiting Record lock, heap no 185 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 89f324f4; asc $ ;; 1: len 6; hex 000000293337; asc )37;; 2: len 7; hex 49000001472fb6; asc I G/ ;; 3: len 30; hex 383834323930326232626563633734323637666638333238646432383065; asc 8842902b2becc74267ff8328dd280e; (total 32 bytes); 4: len 8; hex 8000000053564b2a; asc SVK*;; *** (2) TRANSACTION: TRANSACTION 2700087, ACTIVE 0 sec updating or deleting mysql tables in use 1, locked 1 7 lock struct(s), heap size 1184, 957 row lock(s), undo log entries 1 MySQL thread id 275427, OS thread handle 0x7ff4d00c6700, query id 3949281 85.132.52.203 vesti_user updating UPDATE `online` SET `session`='8842902b2becc74267ff8328dd280e97' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 220 page no 14 n bits 328 index `PRIMARY` of table `vesti_db`.`online` trx id 2700087 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;; Record lock, heap no 185 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 89f324f4; asc $ ;; 1: len 6; hex 000000293337; asc )37;; 2: len 7; hex 49000001472fb6; asc I G/ ;; 3: len 30; hex 383834323930326232626563633734323637666638333238646432383065; asc 8842902b2becc74267ff8328dd280e; (total 32 bytes); 4: len 8; hex 8000000053564b2a; asc SVK*;; Record lock, heap no 186 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 4; hex 89f324f5; asc $ ;; 1: len 6; hex 0000002924fa; asc )$ ;; 2: len 7; hex 1e000002da22d2; asc " ;; 3: len 30; hex 323036313263663739333433393931636662316232356566373337613430; asc 20612cf79343991cfb1b25ef737a40; (total 32 bytes); 4: len 8; hex 8000000053564b2a; asc SVK*;; . . . *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 220 page no 113 n bits 360 index `time` of table `vesti_db`.`online` trx id 3028788 lock_mode X locks rec but not gap waiting Record lock, heap no 123 PHYSICAL RECORD: n_fields 3; compact format; info bits 0 0: len 8; hex 8000000053564f21; asc SVO!;; 1: len 30; hex 373961646130616537383838643165346165396132303738343639393237; asc 79ada0ae7888d1e4ae9a2078469927; (total 32 bytes); 2: len 4; hex 89f33521; asc 5!;; *** WE ROLL BACK TRANSACTION (1) ## 2nd OUTPUT ## ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2014-04-22 16:19:43 7ff15c95a700 *** (1) TRANSACTION: TRANSACTION 3339573, ACTIVE 0 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 3 lock struct(s), heap size 1184, 4 row lock(s) MySQL thread id 338439, OS thread handle 0x7ff4d07e2700, query id 4877382 85.132.52.203 vesti_user updating DELETE FROM `online` WHERE `time` < 1398166245 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 220 page no 65 n bits 392 index `time` of table `vesti_db`.`online` trx id 3339573 lock_mode X waiting Record lock, heap no 114 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 80000000535652e5; asc SVR ;; 1: len 30; hex 343938663531643736316638303335633163646635376135623837623430; asc 498f51d761f8035c1cdf57a5b87b40; (total 32 bytes); 2: len 4; hex 89f34531; asc E1;; *** (2) TRANSACTION: TRANSACTION 3339571, ACTIVE 0 sec updating or deleting mysql tables in use 1, locked 1 9 lock struct(s), heap size 2936, 1218 row lock(s), undo log entries 1 MySQL thread id 338431, OS thread handle 0x7ff15c95a700, query id 4877378 85.132.52.203 vesti_user updating UPDATE `online` SET `session`='2a1dc2ebd7878fea92310650de4245e3' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 220 page no 65 n bits 392 index `time` of table `vesti_db`.`online` trx id 3339571 lock_mode X locks rec but not gap Record lock, heap no 114 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 80000000535652e5; asc SVR ;; 1: len 30; hex 343938663531643736316638303335633163646635376135623837623430; asc 498f51d761f8035c1cdf57a5b87b40; (total 32 bytes); 2: len 4; hex 89f34531; asc E1;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 220 page no 65 n bits 392 index `time` of table `vesti_db`.`online` trx id 3339571 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 114 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 80000000535652e5; asc SVR ;; 1: len 30; hex 343938663531643736316638303335633163646635376135623837623430; asc 498f51d761f8035c1cdf57a5b87b40; (total 32 bytes); 2: len 4; hex 89f34531; asc E1;; *** WE ROLL BACK TRANSACTION (1)
[24 Apr 2014 17:30]
Sveta Smirnova
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 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. Please download source code and read in storage/innobase/include/lock0lock.h: ----<q>---- #define LOCK_INSERT_INTENTION 2048 /*!< this bit is set when we place a waiting gap type record lock request in order to let an insert of an index record to wait until there are no conflicting locks by other transactions on the gap; note that this flag remains set when the waiting lock is granted, or if the lock is inherited to a neighboring record */ ----</q>---- This is insert intention lock which will block inserts, running in parallel and trying to insert into locked gap. Such a lock can be set by any statement.
Portions of this website are copyright © 2001, 2002 The PHP Group
Page generated in 0.057 sec. using MySQL 8.4.7-u6-cloud
Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the
respective copyright holders.
It is not reviewed in advance
by Oracle and does not necessarily represent the opinion of
Oracle or any other party.
Description: Dear experts, From debug script i am getting Deadlock detected error every 5 or 10 minutes with following message: 2014/04/19 22:18:24 [error] [system.db.CDbCommand] Не удалось выполнить CDbCommand::execute(): SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction. Выполнявшийся SQL-запрос: DELETE FROM `online` WHERE `time` < 1397927664. Need help, solving this issue or workaround to this problem. I googled for a hour searching and reading any valuable information about these deadlock condition but even in documentation there no such thing. Below i will provide all necessary related information: MySQL version: mysql> select @@version; +------------+ | @@version | +------------+ | 5.6.10-log | +------------+ 1 row in set (0,00 sec) MySQL server is installed on Centos 6.3 and it is a production server. Table Structure: mysql> show create table online; | online | CREATE TABLE `online` ( `id` int(11) NOT NULL AUTO_INCREMENT, `session` varchar(150) NOT NULL, `time` bigint(20) NOT NULL, PRIMARY KEY (`id`), KEY `time` (`time`,`session`) ) ENGINE=InnoDB AUTO_INCREMENT=166031412 DEFAULT CHARSET=utf8 | 1 row in set (0,00 sec) SQL statements executed on this table are: INSERT INTO `online` (`session`, `time`) VALUES ('d2cc24a6cae9bc0728fb614ff1672f32', '1397922431') DELETE FROM `online` WHERE `time` < 1397921312 UPDATE `online` SET `session`='855b9cc5c0f87076c80105c4de371d00' Explain plans for DMLs: mysql> explain DELETE FROM `online` WHERE `time` < 1397921312\G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: online type: range possible_keys: PRIMARY,time key: time key_len: 8 ref: NULL rows: 1 Extra: Using where 1 row in set (0,00 sec) mysql> explain UPDATE `online` SET `session`='855b9cc5c0f87076c80105c4de371d00'\G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: online type: index possible_keys: PRIMARY,time key: PRIMARY key_len: 4 ref: NULL rows: 1694 Extra: Using temporary 1 row in set (0,00 sec) I reproduced same condition on my Virtual test server..For deep investigation i enabled innodb_print_all_deadlocks: mysql> set global innodb_print_all_deadlocks=ON; Query OK, 0 rows affected (0,00 sec) From First terminal i run update statement for several times and same time i run from second terminal delete statement as shown below: mysql> start transaction; Query OK, 0 rows affected (0,00 sec) mysql> UPDATE `online` SET `session`='a4813bb4c1131ae1f4a59434925f6816'; Query OK, 764 rows affected (0,08 sec) Rows matched: 764 Changed: 764 Warnings: 0 mysql> UPDATE `online` SET `session`='a4813bb4c1131ae1f4a59434925f6816'; Query OK, 0 rows affected (0,00 sec) Rows matched: 764 Changed: 0 Warnings: 0 mysql> UPDATE `online` SET `session`='a4813bb4c1131ae1f4a59434925f6817'; Query OK, 764 rows affected (0,04 sec) Rows matched: 764 Changed: 764 Warnings: 0 mysql> start transaction; Query OK, 0 rows affected (0,00 sec) mysql> DELETE FROM `online` WHERE `time` < 1397940676; ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction So Deadlock occured and here is information from error log: 2014-04-20 11:57:35 7f4e2c84a700InnoDB: transactions deadlock detected, dumping detailed information. 2014-04-20 11:57:35 7f4e2c84a700 *** (1) TRANSACTION: TRANSACTION 8628, ACTIVE 15 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 2, OS thread handle 0x7f4e2c809700, query id 110 localhost root updating DELETE FROM `online` WHERE `time` < 1397940676 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 9 page no 10 n bits 392 index `time` of table `world`.`online` trx id 8628 lock_mode X waiting Record lock, heap no 131 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 800000005352fdcf; asc SR ;; 1: len 30; hex 613438313362623463313133316165316634613539343334393235663638; asc a4813bb4c1131ae1f4a59434925f68; (total 32 bytes); 2: len 4; hex 89e6dc8b; asc ;; *** (2) TRANSACTION: TRANSACTION 8600, ACTIVE 17 sec updating or deleting mysql tables in use 1, locked 1 7 lock struct(s), heap size 1248, 770 row lock(s), undo log entries 3057 MySQL thread id 1, OS thread handle 0x7f4e2c84a700, query id 120 localhost root updating UPDATE `online` SET `session`='a4813bb4c1131ae1f4a59434925f68' *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 9 page no 10 n bits 392 index `time` of table `world`.`online` trx id 8600 lock_mode X locks rec but not gap Record lock, heap no 131 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 800000005352fdcf; asc SR ;; 1: len 30; hex 613438313362623463313133316165316634613539343334393235663638; asc a4813bb4c1131ae1f4a59434925f68; (total 32 bytes); 2: len 4; hex 89e6dc8b; asc ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 9 page no 10 n bits 392 index `time` of table `world`.`online` trx id 8600 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 131 PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 8; hex 800000005352fdcf; asc SR ;; 1: len 30; hex 613438313362623463313133316165316634613539343334393235663638; asc a4813bb4c1131ae1f4a59434925f68; (total 32 bytes); 2: len 4; hex 89e6dc8b; asc ;; *** WE ROLL BACK TRANSACTION (1) ######################################################################## So from this output we can see that TRANSACTION(2): *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 9 page no 10 n bits 392 index `time` of table `world`.`online` trx id 8600 lock_mode X locks rec but not gap So it does not use gap locking as i understand. But another information saying that it is in fact used gap locking? :) *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 9 page no 10 n bits 392 index `time` of table `world`.`online` trx id 8600 lock_mode X locks gap before rec insert intention waiting Any further explanation from your side will really appreciated. How to repeat: If it is necessary i can provide online table dump file. Repeating this condition is too easy as i did it several times for testing and in description wrote all necessary steps. Suggested fix: Waiting for a suggested fix.