MySQL Bugs: #19825: 'SHOW INNODB STATUS' output filled by deadlock output

Bug #19825	'SHOW INNODB STATUS' output filled by deadlock output
Submitted:	15 May 2006 17:57	Modified:	28 Jul 2009 20:07
Reporter:	Douglas Fischer	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.0.21	OS:	Linux (Linux)
Assigned to:	Heikki Tuuri	CPU Architecture:	Any

Description:
This may or may not be considered a bug, though I would be inclined to consider it as such. In the event of a sizeable output of 'LATEST DETECTED DEADLOCK' (i.e. 60k+), the output of 'SHOW INNODB STATUS' will consist only of those sections prior to 'LATEST DETECTED DEADLOCK' and the possibly-truncated deadlock output. This causes scripts that parse the output of 'SHOW INNODB STATUS' to fail in the parsing and, more importantly, prevents any of the latter sections normally included in the output from being present in the output until another, less verbose deadlock occurs or the server is restarted.

How to repeat:
Create a deadlock condition with a sufficient number of locks such that the contents of the 'lock_latest_err_file' approaches 64k in size.

Suggested fix:
innodb_show_status() is nice enough to truncate the list of active transactions if outputting the entire list exceeds the 64k output size. It would be useful if either the contents of the "LATEST DETECTED DEADLOCK" section were similarly truncated, or in the least if the section was properly terminated.

Alternatively, perhaps it would be possible to make the maximum output size of 'SHOW INNODB STATUS' a variable instead of being hard-coded, to allow user control over the output size.

Douglas,

the 64 kB limit comes from the mysql interactive client that does not print longer output.

A workaround is to use:

innodb_monitor

which prints the output to the .err file. That output is not truncated.

I am making this as a feature request. In the future, we could lift the limit in the mysql interactive client.

Regards,

Heikki

I think a better workaround would be to have the LAST DETECTED DEADLOCK section come last, and the TRANSACTIONS section next to last.  I think this will be much more useful for general purposes.  Most people do not want to read through all the records locked by a deadlock, but current transactions is very interesting, as are all the other (smaller) sections.  My personal interest is to enable innotop to more reliably have something to display.  (A Google employee told me they made an internal patch for this purpose too, so I know I'm not the only one who wants it).

It seems some of the information can be repetitive:

\n=====================================\n070320  0:09:18 INNODB MONITOR OUTPUT\n=====================================\nPer second averages calculated from the last 16 seconds\n----------\nSEMAPHORES\n----------\nOS WAIT ARRAY INFO: reservation count 12585160, signal count 7937862\nMutex spin waits 1763705058, rounds 3201915088, OS waits 6167286\nRW-shared spins 14218754, OS waits 2883359; RW-excl spins 15739879, OS waits 2030913\n------------------------\nLATEST DETECTED DEADLOCK\n------------------------\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*!
 ** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n***!
  WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2!
 )\n*** W
E ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE R!
 OLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** WE ROL!
 L BACK TRANSACTION (2)\n*** WE ROLL BACK TRANSACTION (2)\n*** !
 WE ROLL  [..]

Morgan,

what you are seeing might be a result of:
http://bugs.mysql.com/bug.php?id=25494

?

Regards,

Heikki

Looks that way.  Thanks Heikki.

Bug #38835 was marked as a duplicate of this one.

This has been addressed in 5.4 by merging the following google patch:
http://code.google.com/p/google-mysql-tools/wiki/NewShowInnodbStatus

For 5.1/5.0

Easiest way is to manually create a deadlock that is much smaller in size.
For example:

Connection1:
create table t1(a int)engine=innodb;
start transaction;
insert into t1 values (1),(2),(3);

Connection2:
start transaction;
delete from t1 where a=1; #will hang

Connection1:
update t1 set a=2 where a=1;

At this point Connection2 will deadlock, and the SHOW ENGINE INNODB STATUS should be visible again.

Thnaks, Shane Bester.  The workaround by creating an deadlock works for me (using 5.0). Now I can see more important info at the bottom from "show innodb db".