Deadlocks missed by INFORMATION_SCHEMA.INNODB_METRICS lock_deadlocks counter

Bug #1466414 reported by Laurynas Biveinis
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.1
Invalid
Undecided
Unassigned
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
Medium
Laurynas Biveinis
5.7
Fix Released
Medium
Laurynas Biveinis

Bug Description

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";

tags: added: upstream
Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :
Download full text (7.4 KiB)

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
+=====================================
+2015-06-24 11: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
+------------------------
+2015-06-24 11: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:
+...

Read more...

tags: added: innodb
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Related blueprints

Remote bug watches

Bug watches keep track of this bug in other bug trackers.