Percona pt-deadlock-logger doesn't detect deadlock

Question

On a server with performance issues, I'm trying to detect deadlocks with Percona's pt-deadlock-logger

I have this line in a crontab file

0 * * * * root pt-deadlock-logger --daemonize --run-time=1h --dest D=test,t=deadlocks u=root,h=127.0.0.1

Whenever I log into the server I can confirm this is running with ps-ef|grep deadlock

The database and table are set up. My understanding is that I use root access rights, based on a password set in /root/.my.cnf

I tried to simulate a deadlock with (from here: http://forums.mysql.com/read.php?10,193770,193913#msg-193913)

create table test.innodb_deadlock_maker(a int primary key) engine=innodb; 
insert into test.innodb_deadlock_maker(a) values(0), (1); 

-- connection 0 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 0; 
update test.innodb_deadlock_maker set a = 0 where a <> 0; 

-- connection 1 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 1; 
update test.innodb_deadlock_maker set a = 1 where a <> 1;

and this shows a deadloc in the mysql console, but it is not recorded in the database table. Any ideas why not?

Answer 1

Trying to simulate the deadlock as indicated resulted in this for me:

-- connection 0 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 0;
-- does not block, fails immediately with 
-- ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'
update test.innodb_deadlock_maker set a = 0 where a <> 0; 

-- connection 1 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 1; 
-- does block, fails after a timeout with
-- ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
update test.innodb_deadlock_maker set a = 1 where a <> 1;

So, connection 1 waits for connection 0, but connection 0 does not wait on connection 1, only on the COMMIT or ROLLBACK from the application.

This is not a deadlock, and SHOW ENGINE INNODB STATUS does not report a deadlock either.

Changing the sequence to:

-- connection 0 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 0;

-- connection 1 
set transaction isolation level serializable; 
start transaction; 
select * from test.innodb_deadlock_maker where a = 1; 

-- connection 0 
-- does block, waiting on connection 1
update test.innodb_deadlock_maker set a = 0 where a <> 0; 

-- connection 1 
-- would deadlock, fails immediately with
-- ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting
update test.innodb_deadlock_maker set a = 1 where a <> 1;

and this unblocks connection 0:

-- connection 0 
update test.innodb_deadlock_maker set a = 0 where a <> 0; 
-- now unblocked, fails with
-- ERROR 1062 (23000): Duplicate entry '0' for key 'PRIMARY'

In this case, SHOW ENGINE INNODB STATUS reports:

LATEST DETECTED DEADLOCK
------------------------
2013-10-03 11:57:27 0x7f6b60308700
*** (1) TRANSACTION:
TRANSACTION 1297, ACTIVE 47 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1160, 3 row lock(s)
MySQL thread id 2, OS thread handle 140099372304128, query id 13 localhost root Searching rows for update
update test.innodb_deadlock_maker set a = 0 where a <> 0
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 3 n bits 72 index `PRIMARY` of table `test`.`innodb_deadlock_maker` trx id 1297 lock_mode X waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000000508; asc       ;;
 2: len 7; hex a80000011a011c; asc        ;;

*** (2) TRANSACTION:
TRANSACTION 1298, ACTIVE 15 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1160, 2 row lock(s)
MySQL thread id 3, OS thread handle 140099152021248, query id 14 localhost root Searching rows for update
update test.innodb_deadlock_maker set a = 1 where a <> 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 8 page no 3 n bits 72 index `PRIMARY` of table `test`.`innodb_deadlock_maker` trx id 1298 lock mode S locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000000508; asc       ;;
 2: len 7; hex a80000011a011c; asc        ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 3 n bits 72 index `PRIMARY` of table `test`.`innodb_deadlock_maker` trx id 1298 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 4; hex 80000000; asc     ;;
 1: len 6; hex 000000000508; asc       ;;
 2: len 7; hex a80000011a0110; asc        ;;

*** WE ROLL BACK TRANSACTION (2)

I can't speak to pt-deadlock-logger, but I think it relies on the LATEST DETECTED DEADLOCK section in SHOW ENGINE INNODB STATUS, so first please make sure this command actually reports a deadlock.

Answer 2

I don't answer your question directly. But pt-deadlock-logger needn't add to crontab at all.

Once you run pt-deadlock-logger, If no --run-time is specified, pt-deadlock-logger runs forever, checking for deadlocks at every interval. And you also can specify the interval by the option -interval. For more information, please check the link below.

https://www.percona.com/doc/percona-toolkit/2.1/pt-deadlock-logger.html#cmdoption-pt-deadlock-logger--interval