Enabling innodb lock monitor results in no additional lock info

[Peiran Song]

Percona server by default reveals some lock information in SHOW ENGINE INNODB STATUS. However, enabling innodb lock monitor makes no different in the amount of lock details, which makes it impossible to have a complete view of the locks. Below is a test case to show the different behavior between PS and upstream version.

CREATE TABLE innodb_lock_monitor (a int) engine = innodb;

CREATE TABLE `t_lock` (
  `id` int(11) NOT NULL DEFAULT '0',
  `code` int(11) DEFAULT NULL,
  `note` varchar(20) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `idx_1` (`code`)
) ENGINE=InnoDB;

insert into t_lock (id, code) values (1, 10), (2, 20), (3, 30);

begin;
update t_lock set note="bla" where code > 10;

P.S. 5.5.36

---TRANSACTION AFF, ACTIVE 6 sec
3 lock struct(s), heap size 376, 4 row lock(s), undo log entries 2
MySQL thread id 71, OS thread handle 0x7ffa1e15f700, query id 836 localhost 127.0.0.1 msandbox
TABLE LOCK table `test`.`t_lock` trx id AFF lock mode IX
RECORD LOCKS space id 0 page no 436 n bits 72 index `idx_1` of table `test`.`t_lock` trx id AFF lock_mode X locks rec but not gap
RECORD LOCKS space id 0 page no 435 n bits 72 index `PRIMARY` of table `test`.`t_lock` trx id AFF lock_mode X locks rec but not gap

upstream 5.6.19

---TRANSACTION 700033, ACTIVE 14 sec
3 lock struct(s), heap size 360, 4 row lock(s), undo log entries 2
MySQL thread id 39, OS thread handle 0x7f8ca809f700, query id 903 localhost root cleaning up
TABLE LOCK table `test`.`t_lock` trx id 700033 lock mode IX
RECORD LOCKS space id 178 page no 4 n bits 72 index `idx_1` of table `test`.`t_lock` trx id 700033 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80000014; asc ;;
 1: len 4; hex 80000002; asc ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 8000001e; asc ;;
 1: len 4; hex 80000003; asc ;;

RECORD LOCKS space id 178 page no 3 n bits 72 index `PRIMARY` of table `test`.`t_lock` trx id 700033 lock_mode X locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000002; asc ;;
 1: len 6; hex 0000000aae81; asc ;;
 2: len 7; hex 09000001771833; asc w 3;;
 3: len 4; hex 80000014; asc ;;
 4: len 3; hex 626c61; asc bla;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc ;;
 1: len 6; hex 0000000aae81; asc ;;
 2: len 7; hex 09000001771855; asc w U;;
 3: len 4; hex 8000001e; asc ;;
 4: len 3; hex 626c61; asc bla;;

[Valerii Kravchuk (valerii-kravchuk)]

This is easy to confirm on recent PS 5.6.19 as well:

mysql> select version();
+-------------+
| version() |
+-------------+
| 5.6.19-67.0 |
+-------------+
1 row in set (0,00 sec)

mysql> CREATE TABLE innodb_lock_monitor (a int) engine = innodb;
Query OK, 0 rows affected, 1 warning (0,32 sec)

mysql> CREATE TABLE `t_lock` (
    -> `id` int(11) NOT NULL DEFAULT '0',
    -> `code` int(11) DEFAULT NULL,
    -> `note` varchar(20) DEFAULT NULL,
    -> PRIMARY KEY (`id`),
    -> KEY `idx_1` (`code`)
    -> ) ENGINE=InnoDB;
Query OK, 0 rows affected (0,34 sec)

mysql> insert into t_lock (id, code) values (1, 10), (2, 20), (3, 30);
Query OK, 3 rows affected (0,05 sec)
Records: 3 Duplicates: 0 Warnings: 0

mysql>
mysql> begin;
Query OK, 0 rows affected (0,00 sec)

mysql> update t_lock set note="bla" where code > 10;
Query OK, 2 rows affected (0,00 sec)
Rows matched: 2 Changed: 2 Warnings: 0

mysql> select sleep(10);
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10,00 sec)

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2014-07-23 16:12:01 7f2045667700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 18 srv_active, 0 srv_shutdown, 1723 srv_idle
srv_master_thread log flush and writes: 1740
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 29
OS WAIT ARRAY INFO: signal count 28
Mutex spin waits 205, rounds 601, OS waits 12
RW-shared spins 15, rounds 450, OS waits 15
RW-excl spins 1, rounds 60, OS waits 2
Spin rounds per wait: 2.93 mutex, 30.00 RW-shared, 60.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 18287
Purge done for trx's n:o < 18286 undo n:o < 0 state: running but idle
History list length 206
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 18286, ACTIVE 32 sec
3 lock struct(s), heap size 360, 5 row lock(s), undo log entries 2
MySQL thread id 49, OS thread handle 0x7f2045667700, query id 1030 localhost root init
show engine innodb status
TABLE LOCK table `test`.`t_lock` trx id 18286 lock mode IX
RECORD LOCKS space id 177 page no 4 n bits 72 index `idx_1` of table `test`.`t_lock` trx id 18286 lock_mode X
RECORD LOCKS space id 177 page no 3 n bits 72 index `PRIMARY` of table `test`.`t_lock` trx id 18286 lock_mode X locks rec but not gap
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thr...

[Laurynas Biveinis (laurynas-biveinis)]

By code review the following is happening:
1) default InnoDB monitor output in Percona Server always has the basic lock info, regardless of the lock monitor setting. It was not supposed to and that's why enabling the lock monitor does not result in any extra info;
2) The upstream server prints individual locked record info, and PS has moved that to a new innodb_show_verbose_locks variable with default value 0.

So it looks like this bug was reported with the expectation that enabling the lock monitor would have the effect of enabling innodb_show_verbose_locks. Is this correct?

I will fix the default InnoDB monitor output including lock info in a separate bug

[Laurynas Biveinis (laurynas-biveinis)]

bug 1418996

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.1 because there has been no activity for 60 days.]

[Valerii Kravchuk (valerii-kravchuk)]

I see the same problem with recent 5.6.23 - no additional info about rows locked is displayes by PS when innodb_statuis_output=ON and innodb_status_output_locks=ON.

[Valerii Kravchuk (valerii-kravchuk)]

It is expected to see innodb_show_verbose_locks set to ON when two variables menbtioned above are set to ON, this is to be compatible with upstream MySQL and the manual.

[Valerii Kravchuk (valerii-kravchuk)]

Two years later, 5.7.17-12 is still affected...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1528