| Bug #95598 | performance_shema.data_locks shows incorrect lock information | ||
|---|---|---|---|
| Submitted: | 2 Jun 2019 11:10 | Modified: | 7 Jun 2019 15:02 |
| Reporter: | Young Chen | Email Updates: | |
| Status: | Not a Bug | Impact on me: | |
| Category: | MySQL Server: Performance Schema | Severity: | S3 (Non-critical) |
| Version: | 8.0.12 | OS: | CentOS (CentOS release 6.5 (Final)) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | data_locks, insert on duplicate key update | ||
[2 Jun 2019 11:10]
Young Chen
[2 Jun 2019 11:12]
Young Chen
update mysql version :8.0.12
[3 Jun 2019 12:58]
MySQL Verification Team
Hi Mr. Chen, Thank you for your bug report. I do not think that this is a bug, since the gap lock would involve supremum pseudo-record. You can take a look at InnoDB status and find out whether this is true.
[3 Jun 2019 15:32]
Young Chen
Thanks for your quick response Sinisa, maybe I can describe more clearly. mysql> show create table test_young; CREATE TABLE `test_young` ( `id` bigint(20) NOT NULL, `var1` int(11) DEFAULT NULL, `var2` int(11) DEFAULT NULL, PRIMARY KEY (`id`), UNIQUE KEY `idx_var1` (`var1`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='test' mysql> select * from test_young; +-----+------+------+ | id | var1 | var2 | +-----+------+------+ | 10 | 10 | 1 | | 20 | 20 | 1 | | 30 | 30 | 2 | | 40 | 40 | 6 | | 50 | 50 | 6 | | 60 | 60 | 6 | | 70 | 70 | 7 | | 80 | 80 | 8 | | 90 | 90 | 9 | | 100 | 100 | 10 | +-----+------+------+ 10 rows in set (0.00 sec) ****** Let's see Scenario 1 as below: ****** Session 1 is executing sql "insert .. on duplicate update" with an existed UNIQUE KEY 20 of var1 mysql> begin; Query OK, 0 rows affected (0.00 sec) mysql> insert into test_young (id,var1) values (110,20) ON DUPLICATE KEY UPDATE var2=0; Query OK, 2 rows affected (0.00 sec) ****** Let's see the outputs of performance_schema.data_locks on another session: mysql> select ENGINE_LOCK_ID,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks where OBJECT_NAME = 'test_young'; +----------------+-------------+------------+-----------+-----------+-------------+-----------+ | ENGINE_LOCK_ID | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA | +----------------+-------------+------------+-----------+-----------+-------------+-----------+ | 4755:1084 | test_young | NULL | TABLE | IX | GRANTED | NULL | | 4755:27:5:3 | test_young | idx_var1 | RECORD | X | GRANTED | 20 |<------ Should the LOCK_MODE be "X,GAP" ? | 4755:27:4:3 | test_young | PRIMARY | RECORD | X | GRANTED | 20 | +----------------+-------------+------------+-----------+-----------+-------------+-----------+ 3 rows in set (0.00 sec) ****** I think the data 20 on idx_var1 should be with a "next-key" lock (10,20] while session 1 has not committed, so the LOCK_MODE should be "X,GAP" but not "X". ****** Let's start another session to prove it. mysql> insert into test_young (id,var1) values (120,19); ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction ****** Here is the InnoDB status: ------------ TRANSACTIONS ------------ Trx id counter 4758 Purge done for trx's n:o < 4755 undo n:o < 0 state: running but idle History list length 39 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421642928143600, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928142680, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928140840, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928139920, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928139000, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 4755, ACTIVE 1163 sec 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1 MySQL thread id 110, OS thread handle 140167540090624, query id 2457 localhost root -------- FILE I/O --------
[4 Jun 2019 12:16]
MySQL Verification Team
Hi, I have provided you with a possible answer. You did not send back the information that I have asked for. Hence, I am still waiting on your feedback.
[4 Jun 2019 14:37]
Young Chen
****** Here is the "show engine innodb status" outputs, since this is not a deadlock case, so I can only see the information from transactions. ------------ TRANSACTIONS ------------ Trx id counter 4758 Purge done for trx's n:o < 4755 undo n:o < 0 state: running but idle History list length 39 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421642928143600, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928142680, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928140840, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928139920, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 421642928139000, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 4755, ACTIVE 1163 sec 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1 MySQL thread id 110, OS thread handle 140167540090624, query id 2457 localhost root -------- FILE I/O --------
[4 Jun 2019 14:41]
MySQL Verification Team
Hi, You have taken that output in the wrong moment. You have to take it when the locks are held, like with performance_schema output that you provided before.
[4 Jun 2019 15:13]
Young Chen
yes the output was token while the lock is holding.. Since the output was too long, please see the attachment. Thanks
[4 Jun 2019 15:14]
Young Chen
full log
Attachment: 95598.log (application/octet-stream, text), 9.73 KiB.
[5 Jun 2019 11:45]
MySQL Verification Team
Hi, The output from innodb status is not helping, because, evidently you did not enable detailed locks output. This is described in our Reference Manual.
[5 Jun 2019 17:02]
Young Chen
Hi , Here is the detail lock information. It was showing there is "lock_mode X" on the index idx_var1. So I think the outputs from performance_schema.data_locks should be "X,GAP" but not "X" , am I right? ------------ TRANSACTIONS ------------ Trx id counter 5961 Purge done for trx's n:o < 5960 undo n:o < 0 state: running but idle History list length 39 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421650558351200, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 5960, ACTIVE 4 sec 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1 MySQL thread id 16, OS thread handle 140175520671488, query id 235 localhost ldl TABLE LOCK table `ldl`.`test_young` trx id 5960 lock mode IX RECORD LOCKS space id 27 page no 5 n bits 80 index idx_var1 of table `ldl`.`test_young` trx id 5960 lock_mode X Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 80000014; asc ;; 1: len 8; hex 8000000000000014; asc ;; RECORD LOCKS space id 27 page no 4 n bits 80 index PRIMARY of table `ldl`.`test_young` trx id 5960 lock_mode X locks rec but not gap Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0 0: len 8; hex 8000000000000014; asc ;; 1: len 6; hex 000000001748; asc H;; 2: len 7; hex 01000001230327; asc # ';; 3: len 4; hex 80000014; asc ;; 4: len 4; hex 80000000; asc ;;
[6 Jun 2019 12:42]
MySQL Verification Team
Hi Mr. Chen, Actually, no. As lock monitor clearly shows, this is just a simple X lock. No gaps being locked. Otherwise, it would have written there that it is a gap lock. As it does not say so, hence, performance schema output and lock monitor output are both in accordance. InnoDB did not need gap lock there. Also, your output is not from the query and table that you presented in this report.
[6 Jun 2019 14:21]
Young Chen
Dear Sinisa,
Thanks again for your patience, but I think we can discuss more here :)
Your reply: Actually, no. As lock monitor clearly shows, this is just a simple X lock.No gaps being locked.
--> I dont't agree:
1. As you can see from my session 2, value "19" can not be inserted into index idx_var1, it means there must be a gap lock on index idx_var1.
2. For another lock struct on index PRIMARY, you can see lock monitor is showing "lock_mode X locks rec but not gap", it means real X locks but not gap ,and performance schema output shows lock_mode "X"...
Your reply: Otherwise, it would have written there that it is a gap lock. As it does not say so, hence, performance schema output and lock monitor output are both in accordance.
--> please see the two lock structs(on index idx_var1 and PRIMARY) between performance schema output and lock monitor output:
1. if "lock_mode X" = "X" in lock_mode (lock shows on idx_var1)
2. why "lock_mode X locks rec but not gap" = "X" also? (lock shows on PRIMARY)
3. so I dont't think they are both in accordance
Your reply: Also, your output is not from the query and table that you presented in this report.
--> since I had test again to retrieve performance schema output for locks, so the trx ids are not the same. but I had test the case for several times, all of them are with the same result.
Once again for comparison:
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 8, OS thread handle 140215268398848, query id 40 localhost ldl
TABLE LOCK table `ldl`.`test_young` trx id 6426 lock mode IX
RECORD LOCKS space id 27 page no 5 n bits 80 index idx_var1 of table `ldl`.`test_young` trx id 6426 lock_mode X <=======1=========idx_var1
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80000014; asc ;;
1: len 8; hex 8000000000000014; asc ;;
RECORD LOCKS space id 27 page no 4 n bits 80 index PRIMARY of table `ldl`.`test_young` trx id 6426 lock_mode X locks rec but not gap <====2======PRIMARY
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 8; hex 8000000000000014; asc ;;
1: len 6; hex 00000000191a; asc ;;
2: len 7; hex 030000010d0e10; asc ;;
3: len 4; hex 80000014; asc ;;
4: len 4; hex 80000000; asc ;;
mysql> select ENGINE_LOCK_ID,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks where OBJECT_NAME = 'test_young';
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
| ENGINE_LOCK_ID | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
| 6426:1084 | test_young | NULL | TABLE | IX | GRANTED | NULL |
| 6426:27:5:3 | test_young | idx_var1 | RECORD | X | GRANTED | 20 |<========1==========idx_var1, please see LOCK_MODE here
| 6426:27:4:3 | test_young | PRIMARY | RECORD | X | GRANTED | 20 |<======2====PRIMARY, please see LOCK_MODE here
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
3 rows in set (0.01 sec)
[6 Jun 2019 14:38]
MySQL Verification Team
HI, Again, your last output from the lock monitor is not from the query with which you created this bug. So, let us return to the original query. The output is just fine. Because, you have got a duplicate that is matched. Hence, why lock a gap when you are actually doing UPDATE and not INSERT ....... Not a bug.
[6 Jun 2019 15:56]
Young Chen
yes they are the same query, my output are all for my "Scenario 1 : unique key duplicate" only...
below is my original report and query:
------------------------------------------------------------------------------------------------------------------------------------------------
| I'm doubting table performance_shema.data_locks shows incorrect lock information for statement "INSERT ON DUPLICATE KEY UPDATE"
|
| While unique key duplicates : Lock_Mode on unique index should be: X,GAP
| While primary key duplicates : Lock_Mode on PRIMARY should be: X,GAP
------------------------------------------------------------------------------------------------------------------------------------------------
let's just talk about "Scenario 1 : unique key duplicate" only.
***** Step 1: start a transaction and run "insert on duplicate" with a duplicate unique key , not committed
mysql> begin;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into test_young (id,var1) values (110,20) ON DUPLICATE KEY UPDATE var2=0;
Query OK, 2 rows affected (0.00 sec)
***** Step 2: Before the transaction in step one commited, we check the lock information from another session and innodb status:
mysql> select ENGINE_LOCK_ID,OBJECT_NAME,INDEX_NAME,LOCK_TYPE,LOCK_MODE,LOCK_STATUS,LOCK_DATA from performance_schema.data_locks;
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
| ENGINE_LOCK_ID | OBJECT_NAME | INDEX_NAME | LOCK_TYPE | LOCK_MODE | LOCK_STATUS | LOCK_DATA |
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
| 6442:1084 | test_young | NULL | TABLE | IX | GRANTED | NULL |
| 6442:27:5:3 | test_young | idx_var1 | RECORD | X | GRANTED | 20 | <====== My original question is : Lock_mode here should be "X,GAP" but not "X"
| 6442:27:4:3 | test_young | PRIMARY | RECORD | X | GRANTED | 20 |
+----------------+-------------+------------+-----------+-----------+-------------+-----------+
3 rows in set (0.00 sec)
---TRANSACTION 6442, ACTIVE 168 sec
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 8, OS thread handle 140215268398848, query id 60 localhost ldl
TABLE LOCK table `ldl`.`test_young` trx id 6442 lock mode IX
RECORD LOCKS space id 27 page no 5 n bits 80 index idx_var1 of table `ldl`.`test_young` trx id 6442 lock_mode X
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80000014; asc ;;
1: len 8; hex 8000000000000014; asc ;;
RECORD LOCKS space id 27 page no 4 n bits 80 index PRIMARY of table `ldl`.`test_young` trx id 6442 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 8; hex 8000000000000014; asc ;;
1: len 6; hex 00000000192a; asc *;;
2: len 7; hex 020000010c0284; asc ;;
3: len 4; hex 80000014; asc ;;
4: len 4; hex 80000000; asc ;;
***** Step 3: I think the lock mode on idx_var1 should be X with GAP, so I had tried to run to simple insert to prove it in another sesison, you can see it was blocked
mysql> insert into test_young (id,var1) values (120,19);
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
***** If you whink (Lock_mode = 'X' in performance_schema.data_locks) = ('lock_mode X' in enginne innodb status), I think I need to open another ticket to challenge why it shows different for lock on PRIMARY...
[6 Jun 2019 16:00]
Young Chen
As per my understanding, The meaning in "engine innodb status " is : lock_mode X . --> X mode record lock with gap lock_mode X locks rec but not gap --> X mode record lock with no gap So, the "engine innodb status " show correct lock information ,but performance_schema.data_locks didn't...
[7 Jun 2019 12:33]
MySQL Verification Team
Well, your understanding is wrong. What you think about what lock X mode stands for. Unless you point us into the quote from our Reference Manual, where it says otherwise.
[7 Jun 2019 13:35]
Young Chen
Okay, as you mentioned there is just a simple X lock on index idx_var1, could you please advise me what blocked my insert sql in step3 above :) mysql> insert into test_young (id,var1) values (120,19); ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
[7 Jun 2019 13:45]
Young Chen
***** Here is the lock information, we can see it's waiting for "insert intention lock" but blocked by "lock_mode X locks gap before rec" on index idx_var1. ---TRANSACTION 6445, ACTIVE 20 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1 MySQL thread id 13, OS thread handle 140215268398848, query id 95 localhost ldl update insert into test_young (id,var1) values (120,19) ------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 27 page no 5 n bits 80 index idx_var1 of table `ldl`.`test_young` trx id 6445 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 80000014; asc ;; 1: len 8; hex 8000000000000014; asc ;; ------------------ TABLE LOCK table `ldl`.`test_young` trx id 6445 lock mode IX RECORD LOCKS space id 27 page no 5 n bits 80 index idx_var1 of table `ldl`.`test_young` trx id 6445 lock_mode X locks gap before rec insert intention waiting Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 80000014; asc ;; 1: len 8; hex 8000000000000014; asc ;;
[7 Jun 2019 13:56]
Young Chen
This picture is what record-lock shows, please refer to : https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html
Attachment: record_lock.png (image/png, text), 230.69 KiB.
[7 Jun 2019 13:57]
Young Chen
This screen shot is what next-key lock shows, please refer to :https://dev.mysql.com/doc/refman/8.0/en/innodb-locking.html
Attachment: next_key_lock.png (image/png, text), 247.20 KiB.
[7 Jun 2019 14:10]
MySQL Verification Team
The explanation for the gap lock for tuple (120,19) is simple. There is no match , hence no duplicate, hence you get an INSERT. Therefore, it conflicts when an earlier INSERT. This is, however, irrelevant. Do come with the test case where the output from lock monitor shows that there is a gap lock, while in the same momont, P_S does not show a gap lock. If you show that situation and I manage to repeat it, I will be happy to verify this report as a bug in the performance schema. As simple as that.
[7 Jun 2019 14:11]
MySQL Verification Team
One more additional condition. The test case that I have presented above has to be repeatable on 8.0.16. We do not have a habit of chasing already verified or fixed bugs.
[7 Jun 2019 15:02]
Young Chen
Alright, thanks again for your patience Sinisa :) Have a nice day.
[7 Jun 2019 16:13]
MySQL Verification Team
Hi Mr. Chen, I wish you a nice day and nice weekend. I would have preferred that you have come out with a test case as I described, for 8.0.16 !!!! Thank you and when you hit another problem, just file a new report.
