Bug #80927 InnoDB Last Detected Deadlock Not showing full query
Submitted: 31 Mar 2016 15:24 Modified: 5 Oct 2023 21:02
Reporter: Trevor Thackston Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5, 5.5.48 OS:Any
Assigned to: CPU Architecture:Any
Tags: deadlock, engine status, innodb

[31 Mar 2016 15:24] Trevor Thackston
Description:
The last detected deadlock section of the engine status log is only showing 1024 characters (combined) of the thread information and the query. Because we are using Hibernate, some of our generated queries get pretty long - this 1024 character limit is cutting them off before they even reach "where" which is making it very hard to debug these issues. There was an earlier bug about a very similar issue - https://bugs.mysql.com/bug.php?id=7819 - and it looks like the limit was raised to 3000 characters in 5.0.12 as a result of that, but it seems that was overwritten by some later change.

How to repeat:
Write a long query that deadlocks with another query, then use SHOW ENGINE INNODB STATUS. You will see in the Last Detected Deadlock section that the query and its thread information combined do not exceed 1024 characters.

Suggested fix:
Don't limit the query. Since there was hesitation (in regards to cluttering the log) about showing the full query in the previous issue, though, perhaps make the limit on what's printed a configurable setting. It can default to whatever it needs to default to, but it would be useful if we were able to make it show the full query when needed. If a configurable limit is the solution you land upon, though, please do include some option to make it not limit itself. Perhaps a MAX_DEADLOCKED_QUERY_LENGTH variable that, when set to 0 or -1 or so, does not hinder the writing of the log at all.
[1 Apr 2016 6:31] MySQL Verification Team
Hello Trevor,

Thank you for the report.

Thanks,
Umesh
[1 Apr 2016 6:33] MySQL Verification Team
// Imho, this seems to be exists from legacy builds, but easy to see it hitting if you have big query

-- there could be bestter/easier test cases to reproduce than this silly

drop table test.bug;
create table test.bug(a int primary key,ColumnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA INT,ColumnBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB INT,ColumnCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC INT,ColumnDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD INT,ColumnEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE INT,ColumnFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF INT ,ColumnGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG INT ,ColumnHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH INT,ColumnIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIII INT,ColumnJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ INT,ColumnKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK INT,ColumnMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMM INT,ColumnNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN INT,ColumnOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOO INT,ColumnPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPP INT,ColumnQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQ INT,ColumnRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR INT,ColumnSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS INT,ColumnTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT INT,ColumnUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU INT) engine=innodb;
insert into test.bug(a) values(0), (1);

-- connection 0
start transaction;
select * from test.bug where a = 0 LOCK IN SHARE MODE;

-- connection 1
start transaction;
delete from test.bug where a <> 1
AND ColumnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=0
AND ColumnBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB=0
AND ColumnCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC=0
AND ColumnDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD=0
AND ColumnEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE=0
AND ColumnFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF=0
AND ColumnGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG=0
AND ColumnHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH=0
AND ColumnIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIII=0
AND ColumnJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ=0
AND ColumnKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK=0
AND ColumnMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMM=0
AND ColumnNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN=0
AND ColumnOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOO=0
AND ColumnPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPP=0
AND ColumnQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQ=0
AND ColumnRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR=0
AND ColumnSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS=0
AND ColumnTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT=0
AND ColumnUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU=0
;

-- Don't wait for above query to timeout run same query in connection 0
-- connetion 0

delete from test.bug where a <> 1
AND ColumnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=0
AND ColumnBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB=0
AND ColumnCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC=0
AND ColumnDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD=0
AND ColumnEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE=0
AND ColumnFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF=0
AND ColumnGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG=0
AND ColumnHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH=0
AND ColumnIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIII=0
AND ColumnJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ=0
AND ColumnKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK=0
AND ColumnMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMM=0
AND ColumnNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN=0
AND ColumnOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOOO=0
AND ColumnPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPP=0
AND ColumnQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQQ=0
AND ColumnRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRRR=0
AND ColumnSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSSS=0
AND ColumnTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT=0
AND ColumnUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU=0
;
[1 Apr 2016 6:34] MySQL Verification Team
-- 5.5.48/5.5.50 daily build

------------------------
LATEST DETECTED DEADLOCK
------------------------
160401  8:27:14
*** (1) TRANSACTION:
TRANSACTION 304, ACTIVE 11 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 2, OS thread handle 0x7f28a4405700, query id 19 localhost root updating
delete from test.bug where a <> 1
AND ColumnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=0
AND ColumnBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB=0
AND ColumnCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC=0
AND ColumnDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD=0
AND ColumnEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE=0
AND ColumnFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF=0
AND ColumnGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG=0
AND ColumnHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH=0
AND ColumnIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIII=0
AND ColumnJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ=0
AND ColumnKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK=0
AND ColumnMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMM=0
AND ColumnNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 307 n bits 72 index `PRIMARY` of table `test`.`bug` trx id 304 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 23; compact format; info bits 0
 0: len 4; hex 80000000; asc     ;;
 1: len 6; hex 000000000302; asc       ;;
 2: len 7; hex 83000001340110; asc     4  ;;
 3: SQL NULL;
 4: SQL NULL;
 5: SQL NULL;
 6: SQL NULL;
 7: SQL NULL;
 8: SQL NULL;
 9: SQL NULL;
 10: SQL NULL;
 11: SQL NULL;
 12: SQL NULL;
 13: SQL NULL;
 14: SQL NULL;
 15: SQL NULL;
 16: SQL NULL;
 17: SQL NULL;
 18: SQL NULL;
 19: SQL NULL;
 20: SQL NULL;
 21: SQL NULL;
 22: SQL NULL;

*** (2) TRANSACTION:
TRANSACTION 303, ACTIVE 24 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1248, 2 row lock(s)
MySQL thread id 1, OS thread handle 0x7f28a4446700, query id 20 localhost root updating
delete from test.bug where a <> 1
AND ColumnAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=0
AND ColumnBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBBB=0
AND ColumnCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCCC=0
AND ColumnDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDDD=0
AND ColumnEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE=0
AND ColumnFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF=0
AND ColumnGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG=0
AND ColumnHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHHH=0
AND ColumnIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIIII=0
AND ColumnJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ=0
AND ColumnKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKKK=0
AND ColumnMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMMM=0
AND ColumnNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNNN
*** (2) HOLDS THE LOCK(S):
[5 Oct 2023 21:02] Philip Olson
Posted by developer:
 
Fixed as of the upcoming MySQL Server 5.7.44/8.0.35/8.2.0 releases, and NDB Cluster 5.7.44-ndb-7.5.32/5.7.44-ndb-7.6.28 releases, and here's the proposed changelog entry from the documentation team:

The last detected deadlock section of the engine status log was only
showing 1024 characters for the combined thread and query information.
Fixing by removing the printed query string limit.

Thank you for the bug report.
[21 Nov 2023 10:21] Stefan Paul Noack
Unfortunately this is not true. The limit has not been removed, just raised to 3000 characters, which still is not enough to see large queries: https://github.com/mysql/mysql-server/commit/0a13dadbe71c0b6efb7b5e04de2f3f6f873ce089#diff...