Pt-deadlock-logger ignoring deadlock

Polyglot Projects Percona Toolkit
1

Testing pt-deadlock-logger 3.6.0 with mariadb 11.3.2 , 10.6.16:
Run pt-deadlock-logger:

pt-deadlock-logger --log /var/log/dead.log --interval=5s --daemonize

After try to create deadlock

1st transaction

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> select * from t1 where id=5 lock in share mode;
+------+
| id   |
+------+
|    5 |
+------+
1 row in set (0.000 sec)

MariaDB [test]>

Second transaction

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> select * from t1 where id=5 lock in share mode;
+------+
| id   |
+------+
|    5 |
+------+
1 row in set (0.000 sec)

MariaDB [test]> update t1 set id=6 where id=5;

And after that on first transaction:

MariaDB [test]> update t1 set id=6 where id=5;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
MariaDB [test]>

In innodb logs i see deadlock

------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-06-27 09:23:54 0x7f496c1f1640
*** (1) TRANSACTION:
TRANSACTION 169171, ACTIVE 48 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 7 row lock(s)
MariaDB thread id 32, OS thread handle 139953323316800, query id 99 localhost root Updating
update t1 set id=6 where id=5
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169171 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

*** CONFLICTING WITH:
RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169171 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df06; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df07; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df08; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df09; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000005; asc     ;;

RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169170 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df06; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df07; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df08; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df09; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000005; asc     ;;


*** (2) TRANSACTION:
TRANSACTION 169170, ACTIVE 22 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 7 row lock(s)
MariaDB thread id 33, OS thread handle 139953331709504, query id 98 localhost root Updating
update t1 set id=6 where id=5
*** WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169170 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

*** CONFLICTING WITH:
RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169171 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df06; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df07; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df08; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df09; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000005; asc     ;;

RECORD LOCKS space id 444 page no 3 n bits 8 index GEN_CLUST_INDEX of table `test`.`t1` trx id 169170 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df05; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df06; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df07; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df08; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000078df09; asc    x  ;;
 1: len 6; hex 000000000000; asc       ;;
 2: len 7; hex 80000000000000; asc        ;;
 3: len 4; hex 80000005; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

But no info in log file

~# cat /var/log/dead.log

~#
2

Found several problems (temporary fix and check - now work)
1.

sub parse_deadlocks {
....
....
my ( $thread_line ) = $body =~ m/^(MySQL thread id .*)$/m;
...
...
         if ( $thread_line ) {
            # These parts can always be gotten.
            ( $mysql_thread_id, $query_id )
               = $thread_line =~ m/^MySQL thread id $d,.* query id $d/m;
...
...
         my ( $query_text ) = $body =~ m/\nMySQL thread id .*\n((?s).*)/;
         $query_text =~ s/\s+$//;
         $query_text =~ s/\s+/ /g;

for MariaDB need to check “MariaDB” string as alternative

sub main {
....
....
....
            if ( !$o->get('quiet') ) {
               print join($sep, @cols), "\n";
               foreach my $txn (
                  sort { $a->{thread} <=> $b->{thread} } values %txns
               ) {
                  $txn->{query} =~ s/\s+/ /g;
                  print join($sep, map { $txn->{$_} } @cols), "\n";
               }
            }
....
....

Here in

print join($sep, map { $txn->{$_} } @cols), "\n";

some hash keys not defined (txn_id,txn_time…) and in this case we have error
temporary fix it by

print join($sep, map { $txn->{$_} //'?'} @cols), "\n";
3

@PavelVD Please check https://jira.percona.com/ for existing bugs on this. If you can’t find one, please open a new Percona Toolkit bug with your findings. Our Toolkit team is quite active. Having test cases like yours really helps them out. We just released Toolkit 3.6 which fixed many long standing bugs.