Deadlocks missed by INFORMATION_SCHEMA.INNODB_METRICS lock_deadlocks counter

[Laurynas Biveinis]

Copy of http://bugs.mysql.com/bug.php?id=77399 (the testcase is based on percona_innodb_deadlock_count with I_S.I_M support added)

[18 Jun 8:22] Laurynas Biveinis
Description:
Some deadlocks do not bump the INFORMATION_SCHEMA.INNODB_METRICS lock_deadlocks counter. The MTR below will result in

SELECT NAME, COUNT, COMMENT FROM INFORMATION_SCHEMA.INNODB_METRICS WHERE NAME="lock_deadlocks";
NAME COUNT COMMENT
lock_deadlocks 0 Number of deadlocks

But if you check ie. engine status, you will see

------------------------
LATEST DETECTED DEADLOCK
------------------------
2015-06-18 11:20:16 10d7a0000
*** (1) TRANSACTION:
TRANSACTION 1292, ACTIVE 0 sec starting index read
... info ...

How to repeat:
--source include/have_innodb.inc

connect (con1,localhost,root,,);
connect (con2,localhost,root,,);

create table t(a INT PRIMARY KEY, b INT) engine=InnoDB;
insert into t values(2,1);
insert into t values(1,2);

SET GLOBAL innodb_monitor_reset=lock_deadlocks;

connection con1;
BEGIN; SELECT b FROM t WHERE a=1 FOR UPDATE;

connection con2;
BEGIN; SELECT b FROM t WHERE a=2 FOR UPDATE;

connection con1;
SEND SELECT b FROM t WHERE a=2 FOR UPDATE;

connection con2;
SEND SELECT b FROM t WHERE a=1 FOR UPDATE;

connection con1;
--error 0,ER_LOCK_DEADLOCK
reap;
ROLLBACK;

connection con2;
--error 0,ER_LOCK_DEADLOCK
reap;
ROLLBACK;

connection default;

SELECT NAME, COUNT, COMMENT FROM INFORMATION_SCHEMA.INNODB_METRICS WHERE NAME="lock_deadlocks";

[Valerii Kravchuk (valerii-kravchuk)]

This is easy to confirm on 5.6 as well (I've added query_veritval SHGOW ENGINE INNODB STATUS; to the MTR test case):

...
TEST RESULT TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1466414 [ fail ]
        Test ended at 2015-06-24 11:03:56

CURRENT_TEST: main.1466414
--- /home/openxs/dbs/p5.6/mysql-test/r/1466414.result 2015-06-24 11:00:55.227564574 +0300
+++ /home/openxs/dbs/p5.6/mysql-test/var/log/1466414.reject 2015-06-24 11:03:56.178302839 +0300
@@ -0,0 +1,160 @@
+create table t(a INT PRIMARY KEY, b INT) engine=InnoDB;
+insert into t values(2,1);
+insert into t values(1,2);
+SET GLOBAL innodb_monitor_reset=lock_deadlocks;
+BEGIN;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+2
+BEGIN;
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+b
+1
+SELECT b FROM t WHERE a=2 FOR UPDATE;
+SELECT b FROM t WHERE a=1 FOR UPDATE;
+b
+1
+ROLLBACK;
+ROLLBACK;
+SHOW ENGINE INNODB STATUS;
+Type InnoDB
+Name
+Status
+=====================================
[phone]:03:56 7f35a856e700 INNODB MONITOR OUTPUT
+=====================================
+Per second averages calculated from the last 1 seconds
+-----------------
+BACKGROUND THREAD
+-----------------
+srv_master_thread loops: 0 srv_active, 0 srv_shutdown, 0 srv_idle
+srv_master_thread log flush and writes: 0
+----------
+SEMAPHORES
+----------
+OS WAIT ARRAY INFO: reservation count 4
+OS WAIT ARRAY INFO: signal count 4
+Mutex spin waits 2, rounds 60, OS waits 2
+RW-shared spins 2, rounds 60, OS waits 2
+RW-excl spins 0, rounds 0, OS waits 0
+Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
+------------------------
+LATEST DETECTED DEADLOCK
+------------------------
[phone]:03:56 7f35a84ec700
+*** (1) TRANSACTION:
+TRANSACTION 1293, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 3, OS thread handle 0x7f35a852d700, query id 33 localhost root statistics
+SELECT b FROM t WHERE a=2 FOR UPDATE
+*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1293 lock_mode X locks rec but not gap waiting
+*** (2) TRANSACTION:
+TRANSACTION 1294, ACTIVE 0 sec starting index read
+mysql tables in use 1, locked 1
+3 lock struct(s), heap size 360, 2 row lock(s)
+MySQL thread id 4, OS thread handle 0x7f35a84ec700, query id 34 localhost root statistics
+SELECT b FROM t WHERE a=1 FOR UPDATE
+*** (2) HOLDS THE LOCK(S):
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap
+*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
+RECORD LOCKS space id 6 page no 3 n bits 72 index `PRIMARY` of table `test`.`t` trx id 1294 lock_mode X locks rec but not gap waiting
+*** WE ROLL BACK TRANSACTION (2)
+------------
+TRANSACTIONS
+------------
+Trx id counter 1297
+Purge done for trx's n:o < 1297 undo n:o < 0 state: running but idle
+History list length 2
+LIST OF TRANSACTIONS FOR EACH SESSION:
+...

[Laurynas Biveinis (laurynas-biveinis)]

https://github.com/percona/percona-server/pull/537, https://github.com/percona/percona-server/pull/538

[Shahriyar Rzayev (rzayev-sehriyar)]

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