| 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.
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.