diff --git a/bin/pt-deadlock-logger b/bin/pt-deadlock-logger index d6cf6d29..a223fd50 100755 --- a/bin/pt-deadlock-logger +++ b/bin/pt-deadlock-logger @@ -3757,7 +3757,8 @@ my $d = qr/(\d+)/; # Digit my $t = qr/((?:\d+ \d+)|(?:[A-Fa-f0-9]+))/; # Transaction ID my $i = qr/((?:\d{1,3}\.){3}\d+)/; # IP address my $n = qr/([^`\s]+)/; # MySQL object name -my $w = qr/(\w+)/; # Words +my $u = qr/(\S+)/; # Username. This is somewhat wrong, but + # usernames with spaces are rare enough. my $s = qr/(\d{6} .\d:\d\d:\d\d)/; # InnoDB timestamp # A thread's proc_info can be at least 98 different things I've found in the @@ -4082,7 +4083,7 @@ sub parse_deadlocks { # the most useful marker for where I have to start guessing. ( $hostname, $ip ) = $thread_line =~ m/query id \d+(?: ([A-Za-z]\S+))? $i/m; if ( defined $ip ) { - ($user, $query_status) = $thread_line =~ m/$ip $w(?: (.*))?$/; + ($user, $query_status) = $thread_line =~ m/$ip $u(?: (.*))?$/; } else { # OK, there wasn't an IP address. @@ -4094,7 +4095,7 @@ sub parse_deadlocks { # query_status. # It's basically impossible to know which is which. ( $hostname, $user, $query_status ) = $thread_line - =~ m/query id \d+(?: ([A-Za-z]\S+))?(?: $w(?: (.*))?)?$/m; + =~ m/query id \d+(?: ([A-Za-z]\S+))?(?: $u(?: (.*))?)?$/m; } else { $user = 'system user'; @@ -4387,6 +4388,10 @@ held lock, you're looking at the same lock, so of course you'd prefer to see both wait-for locks and get more information. If the two waited-for locks are not on the same table, more than two transactions were involved in the deadlock. +Finally, keep in mind that, because usernames with spaces are not quoted by +InnoDB, the tool will generally misreport the second word of these usernames +as the hostname. + =head1 OPTIONS This tool accepts additional command-line arguments. Refer to the diff --git a/t/pt-deadlock-logger/bugs.t b/t/pt-deadlock-logger/bugs.t index 621ec5ce..29f29c41 100644 --- a/t/pt-deadlock-logger/bugs.t +++ b/t/pt-deadlock-logger/bugs.t @@ -9,7 +9,7 @@ BEGIN { use strict; use warnings FATAL => 'all'; use English qw(-no_match_vars); -use Test::More tests => 1; +use Test::More; use PerconaTest; use Sandbox; @@ -67,7 +67,60 @@ is_deeply( "Bug 903443: pt-deadlock-logger parses the thread id incorrectly for MySQL 5.5", ); +# ############################################################################# +# https://bugs.launchpad.net/percona-toolkit/+bug/1082104 +# pt-deadlock-logger problem when the user have a dash in the name +# ############################################################################# + +$innodb_status_sample = load_file("t/pt-deadlock-logger/samples/bug_1082104.txt"); + +is_deeply( + pt_deadlock_logger::parse_deadlocks($innodb_status_sample), + { + '1' => { + db => 'test', + hostname => 'localhost', + id => 1, + idx => 'PRIMARY', + ip => '', + lock_mode => 'X', + lock_type => 'RECORD', + query => 'update a set movie_id=96 where id =2', + server => '', + tbl => 'a', + thread => '19', + ts => '2011-12-12T22:52:42', + txn_id => 0, + txn_time => '161', + user => 'ro-ot', + victim => 0, + wait_hold => 'w' + }, + '2' => { + db => 'test', + hostname => 'localhost', + id => 2, + idx => 'PRIMARY', + ip => '', + lock_mode => 'X', + lock_type => 'RECORD', + query => 'update a set movie_id=98 where id =4', + server => '', + tbl => 'a', + thread => '18', + ts => '2011-12-12T22:52:42', + txn_id => 0, + txn_time => '1026', + user => 'ro-ot', + victim => 1, + wait_hold => 'w' + } + }, + "Bug 1082104: pt-deadlock-logger shows host as user when the username has a dash in the name", +); + # ############################################################################# # Done. # ############################################################################# +done_testing; exit; diff --git a/t/pt-deadlock-logger/samples/bug_1082104.txt b/t/pt-deadlock-logger/samples/bug_1082104.txt new file mode 100644 index 00000000..0003d9de --- /dev/null +++ b/t/pt-deadlock-logger/samples/bug_1082104.txt @@ -0,0 +1,53 @@ +===================================== +070915 15:34:37 INNODB MONITOR OUTPUT +===================================== +Per second averages calculated from the last 24 seconds +------------------------ +LATEST DETECTED DEADLOCK +------------------------ +111212 22:52:42 +*** (1) TRANSACTION: +TRANSACTION 3405, ACTIVE 161 sec starting index read +mysql tables in use 1, locked 1 +LOCK WAIT 3 lock struct(s), heap size 376, 3 row lock(s), undo log entries 2 +MySQL thread id 19, OS thread handle 0x7fac301e4700, query id 180 localhost ro-ot Updating +update a set movie_id=96 where id =2 +*** (1) WAITING FOR THIS LOCK TO BE GRANTED: +RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3405 lock_mode X locks rec but not gap waiting +Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 + 0: len 4; hex 80000002; asc ;; + 1: len 6; hex 000000003404; asc 4 ;; + 2: len 7; hex 040000163b2515; asc ;% ;; + 3: len 4; hex 80000063; asc c;; + 4: len 1; hex 01; asc ;; + 5: len 8; hex 8000124a7c1acb8c; asc J| ;; + +*** (2) TRANSACTION: +TRANSACTION 3404, ACTIVE 1026 sec starting index read +mysql tables in use 1, locked 1 +3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1 +MySQL thread id 18, OS thread handle 0x7fac30225700, query id 181 localhost ro-ot Updating +update a set movie_id=98 where id =4 +*** (2) HOLDS THE LOCK(S): +RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3404 lock_mode X locks rec but not gap +Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 + 0: len 4; hex 80000002; asc ;; + 1: len 6; hex 000000003404; asc 4 ;; + 2: len 7; hex 040000163b2515; asc ;% ;; + 3: len 4; hex 80000063; asc c;; + 4: len 1; hex 01; asc ;; + 5: len 8; hex 8000124a7c1acb8c; asc J| ;; + +*** (2) WAITING FOR THIS LOCK TO BE GRANTED: +RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`a` trx id 3404 lock_mode X locks rec but not gap waiting +Record lock, heap no 5 PHYSICAL RECORD: n_fields 6; compact format; info bits 0 + 0: len 4; hex 80000004; asc ;; + 1: len 6; hex 000000003405; asc 4 ;; + 2: len 7; hex 0500000e7017e8; asc p ;; + 3: len 4; hex 80000062; asc b;; + 4: len 1; hex 01; asc ;; + 5: len 8; hex 8000124a7c1acbb6; asc J| ;; + +*** WE ROLL BACK TRANSACTION (2) +END OF INNODB MONITOR OUTPUT +============================