Bug #93733 Different Lock info in show engine innodb status ouput for 5.6 and 5.7
Submitted: 24 Dec 2018 14:33 Modified: 12 Mar 2019 13:58
Reporter: lalit Choudhary Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: innodb

[24 Dec 2018 14:33] lalit Choudhary
Description:
 MySQL show engine innodb status output print different Lock info for 5.6 and 5.7 when transaction_isolation REPEATABLE-READ.

Issue not reproducible with transaction_isolation | READ-COMMITTED

How to repeat:

MySQL 5.6.42

[session 1] 
mysql> show session variables like '%iso%'; 
+---------------+-----------------+ 
| Variable_name | Value | 
+---------------+-----------------+ 
| tx_isolation | REPEATABLE-READ | 
+---------------+-----------------+ 
1 row in set (0.00 sec)

mysql> show variables like 'innodb_status%'; 
+----------------------------+-------+ 
| Variable_name | Value | 
+----------------------------+-------+ 
| innodb_status_output | ON | 
| innodb_status_output_locks | ON | 
+----------------------------+-------+ 
2 rows in set (0.00 sec)

mysql> use test; 
Reading table information for completion of table and column names 
You can turn off this feature to get a quicker startup with -A

Database changed

mysql> select * from dup_tb; 
+----+-----------+---------+---------------+---------------------+ 
| id | data_type | data_id | document_data | update_at | 
+----+-----------+---------+---------------+---------------------+ 
| 1 | aaa | aaa | aaa | 2018-12-21 11:13:11 | 
| 2 | aab | aab | aab | 2018-12-21 11:13:24 | 
| 3 | aac | aac | aac | 2018-12-21 11:13:37 | 
+----+-----------+---------+---------------+---------------------+ 
3 rows in set (0.00 sec)

mysql> start transaction; 
Query OK, 0 rows affected (0.00 sec)

mysql> insert into dup_tb values (null, 'aac','aac','aac', null) 
-> on duplicate key update update_at=current_date(); 
Query OK, 1 row affected (0.00 sec)

mysql>

[session 2] 
mysql> show engine innodb status \G 

------------
TRANSACTIONS
------------
Trx id counter 1811
Purge done for trx's n:o < 1811 undo n:o < 0 state: running but idle
History list length 4
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 4, OS thread handle 0x7f11c27bb700, query id 44 localhost msandbox init
show engine innodb status
---TRANSACTION 1806, ACTIVE 3 sec
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 3, OS thread handle 0x7f11c27fd700, query id 43 localhost msandbox
TABLE LOCK table `test`.`dup_tb` trx id 1806 lock mode IX

MySQL 5.7.24

[session 1] 

mysql> show session variables like '%iso%'; 
+-----------------------+-----------------+ 
| Variable_name | Value | 
+-----------------------+-----------------+ 
| transaction_isolation | REPEATABLE-READ | 
| tx_isolation | REPEATABLE-READ | 
+-----------------------+-----------------+ 
2 rows in set (0.01 sec)

mysql> show variables like 'innodb_status%'; 
+----------------------------+-------+ 
| Variable_name | Value | 
+----------------------------+-------+ 
| innodb_status_output | ON | 
| innodb_status_output_locks | ON | 
+----------------------------+-------+ 
2 rows in set (0.00 sec)

mysql> select * from dup_tb; 
+----+-----------+---------+---------------+---------------------+ 
| id | data_type | data_id | document_data | update_at | 
+----+-----------+---------+---------------+---------------------+ 
| 1 | aaa | aaa | aaa | 2018-12-21 10:45:48 | 
| 2 | aab | aab | aab | 2018-12-21 10:46:03 | 
| 3 | aac | aac | aac | 2018-12-21 10:46:18 | 
+----+-----------+---------+---------------+---------------------+ 
3 rows in set (0.00 sec)

mysql> start transaction; 
Query OK, 0 rows affected (0.00 sec)

mysql> insert into dup_tb values (null, 'aac','aac','aac', null) 
-> on duplicate key update update_at=current_date(); 
Query OK, 1 row affected (0.00 sec)

[session 2] 
mysql> show engine innodb status \G 

------------
TRANSACTIONS
------------
Trx id counter 1812
Purge done for trx's n:o < 1812 undo n:o < 0 state: running but idle
History list length 4
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422019193318112, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1807, ACTIVE 6 sec
3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 2, OS thread handle 140543812695808, query id 23 localhost msandbox
TABLE LOCK table `test`.`dup_tb` trx id 1807 lock mode IX
RECORD LOCKS space id 25 page no 4 n bits 72 index uk1 of table `test`.`dup_tb` trx id 1807 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 LOCKS space id 25 page no 4 n bits 72 index uk1 of table `test`.`dup_tb` trx id 1807 lock_mode X locks gap before rec
Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 3; hex 616163; asc aac;;
 1: len 3; hex 616163; asc aac;;
 2: len 4; hex 5c20e402; asc \   ;;
 3: len 8; hex 8000000000000004; asc         ;;

Here the issue is,
for 5.6 : it only table table LOCK (Intention Locks)
for 5.7 : it taking table LOCK (Intention Locks) as well as Row lock(Record LOCK)

Suggested fix:
Both versions should print the same information if there is no change in MySQL innodb locking mechanism.
[12 Mar 2019 13:58] MySQL Verification Team
Hi,

Actually, there was a change in locking since the two versions. It was caused by ON DUPLICATE cause.

It is extremely hard to point to the bug, internal report or WorkLog entry, since there were thousands of changes interim.

On our Documentation pages, there is a revision history for 5.7, os if you have time, you can find the change.