Observed in Percona Server 5.6.16 and 5.6.17 that SQL statement sometime is missing in SHOW ENGINE INNODB STATUS output both in the LASTEST DETECTED DEADLOCK section and TRANSACTIONS section. Stock 5.6 and PS 5.5 don't seem affected, but testing was limited.
This is a customer's data with PS 5.6.17. Autocommit is on, and TRANSACTION1's SQL statement is not printed.
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-06-10 17:01:36 7f4afe16d700
*** (1) TRANSACTION:
TRANSACTION 505926011, ACTIVE 0 sec fetching rows
mysql tables in use 2, locked 2
LOCK WAIT 4 lock struct(s), heap size 1184, 10 row lock(s)
MySQL thread id 34797, OS thread handle 0x7f4af79a6700, query id 55052467 10.1.1.111 recall Sending data
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1373356 page no 552596 n bits 112 index `PRIMARY` of table `outcalls`.`outcalls_complete` trx id 505926011 lock mode S locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 505925999, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
133 lock struct(s), heap size 13864, 1519 row lock(s)
MySQL thread id 83098, OS thread handle 0x7f4afe16d700, query id 55052397 10.1.9.29 recall Searching rows for update
UPDATE outcalls_complete set status = status-8000 where status >= 9000 AND node = NAME_CONST('nClusterNode',5093)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1373356 page no 552596 n bits 112 index `PRIMARY` of table `outcalls`.`outcalls_complete` trx id 505925999 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1373356 page no 552596 n bits 112 index `PRIMARY` of table `outcalls`.`outcalls_complete` trx id 505925999 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)
I produced a deadlock on PS 5.6.16 and noticed the same thing. Two running SQLs, but statement from TRANSACTION1 is missing.
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-06-10 10:01:18 7f81ccac7700
*** (1) TRANSACTION:
TRANSACTION 10994, ACTIVE 3 sec setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 108, OS thread handle 0x7f81ccb08700, query id 448 localhost 127.0.0.1 msandbox update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test`.`child` trx id 10994 lock mode AUTO-INC waiting
*** (2) TRANSACTION:
TRANSACTION 10993, ACTIVE 7 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 1
MySQL thread id 132, OS thread handle 0x7f81ccac7700, query id 445 localhost 127.0.0.1 msandbox update
insert into child (p_id) values (2)
*** (2) HOLDS THE LOCK(S):
TABLE LOCK table `test`.`child` trx id 10993 lock mode AUTO-INC
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 21 page no 3 n bits 72 index `PRIMARY` of table `test`.`parent` trx id 10993 lock mode S locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)
More testing showed that this is not limited to transactions involved in deadlock. With a large table, running an UPDATE statement, and meanwhile, look at the SHOW ENGINE INNODB STATUS, the running statement is not printed in the TRANSACTION section.
mysql> update t1 set name = 'ah';
---TRANSACTION 11305, ACTIVE 1 sec fetching rows
mysql tables in use 1, locked 1
2855 lock struct(s), heap size 357928, 791828 row lock(s), undo log entries 788975
MySQL thread id 202, OS thread handle 0x7f81ccb49700, query id 790 localhost 127.0.0.1 msandbox updating
TABLE LOCK table `test`.`t1` trx id 11305 lock mode IX
RECORD LOCKS space id 34 page no 5 n bits 528 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 6 n bits 360 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 3776 n bits 344 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 7 n bits 360 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 3840 n bits 344 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 10 n bits 360 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 3904 n bits 344 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 12 n bits 360 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
RECORD LOCKS space id 34 page no 384 n bits 344 index `PRIMARY` of table `test`.`t1` trx id 11305 lock_mode X
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
Again limited test on PS 5.1 and PS 5.5 didn't reproduce it.
In PS 5.6, a test case to produce a deadlock with running statements and observe missing statement in deadlock section :
Prepare the data:
-------
use test;
create table parent (id int, name varchar(20), primary key (id)) engine = innodb;
create table child (id int auto_increment, p_id int, primary key (id), key idx_p_id (p_id), constraint fk_p_id foreign key (p_id) references parent (id) ) engine = innodb;
insert into parent values (1, "foo"), (2,"blah");
insert into child (p_id) values (1);
for i in {1..20}; do echo $i; echo "insert into child (p_id) select t.p_id from child t" | mysql test; done
Run the test:
-------------------
session1:
echo “insert into child (p_id) select t.p_id from child t” | mysql test ;
session2: while session1 running
mysql> insert into child (p_id) value (2);
session3, while session1 and session2 running
mysql> begin; update parent set name = “aha” where id = 2; insert into child (p_id) value (1);
When session1 finishes, session2 and 3 would result in deadlock.
mysql> show engine innodb status\G
-------
LATEST DETECTED DEADLOCK
-------
2014-06-12 11:44:45 7f81ccb8a700
*** (1) TRANSACTION:
TRANSACTION 12040, ACTIVE 4 sec setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 279, OS thread handle 0x7f81ccac7700, query id 1244 localhost 127.0.0.1 msandbox update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `test`.`child` trx id 12040 lock mode AUTO-INC waiting
*** (2) TRANSACTION:
TRANSACTION 12039, ACTIVE 7 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 1
MySQL thread id 280, OS thread handle 0x7f81ccb8a700, query id 1241 localhost 127.0.0.1 msandbox update
insert into child (p_id) value (2)
*** (2) HOLDS THE LOCK(S):
TABLE LOCK table `test`.`child` trx id 12039 lock mode AUTO-INC
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 21 page no 3 n bits 72 index `PRIMARY` of table `test`.`parent` trx id 12039 lock mode S locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)
To observe missing statement in TRANSACTION section, use the above data:
session1:
mysql > update child set p_id = 2;
session 2 while session 1 running:
mysql> show engine innodb status\G
---TRANSACTION 12058, ACTIVE 2 sec updating or deleting
mysql tables in use 1, locked 1
109 lock struct(s), heap size 30248, 58258 row lock(s), undo log entries 58152
MySQL thread id 280, OS thread handle 0x7f81ccb8a700, query id 1247 localhost 127.0.0.1 msandbox updating
TABLE LOCK table `test`.`child` trx id 12058 lock mode IX
RECORD LOCKS space id 39 page no 5 n bits 624 index `PRIMARY` of table `test`.`child` trx id 12058 lock_mode X
TABLE LOCK table `test`.`parent` trx id 12058 lock mode IS
RECORD LOCKS space id 21 page no 3 n bits 72 index `PRIMARY` of table `test`.`parent` trx id 12058 lock mode S locks rec but not gap
RECORD LOCKS space id 39 page no 6 n bits 624 index `PRIMARY` of table `test`.`child` trx id 12058 lock_mode X
RECORD ...