This is a backport of "WL#5674 InnoDB: report all deadlocks (Bug#1784)"

from MySQL 5.6 into MySQL 5.5

Will close Bug#14515889 BACKPORT OF INNODB DEADLOCK LOGGING TO 5.5

The original implementation is in
vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn

Approved by:	Jimmy (rb:1535)

mysql-test/suite/sys_vars/r/innodb_print_all_deadlocks_basic.result

+SELECT @@innodb_print_all_deadlocks;
+@@innodb_print_all_deadlocks
+0
+SET GLOBAL innodb_print_all_deadlocks=1;
+CREATE TABLE t1 (c1 INT, PRIMARY KEY (c1)) ENGINE=INNODB;
+INSERT INTO t1 VALUES (123);
+CREATE TABLE t2 (c2 INT, PRIMARY KEY (c2)) ENGINE=INNODB;
+INSERT INTO t2 VALUES (456);
+BEGIN;
+SELECT * FROM t1 FOR UPDATE;
+c1
+123
+BEGIN;
+SELECT * FROM t2 FOR UPDATE;
+c2
+456
+SELECT * FROM t2 FOR UPDATE;
+SELECT * FROM t1 FOR UPDATE;
+ERROR 40001: Deadlock found when trying to get lock; try restarting transaction
+DROP TABLE t2;
+DROP TABLE t1;
+SET GLOBAL innodb_print_all_deadlocks=default;

mysql-test/suite/sys_vars/t/innodb_print_all_deadlocks_basic.test

+#
+# innodb_print_all_deadlocks
+#
+
+-- source include/have_innodb.inc
+
+SELECT @@innodb_print_all_deadlocks;
+
+SET GLOBAL innodb_print_all_deadlocks=1;
+
+CREATE TABLE t1 (c1 INT, PRIMARY KEY (c1)) ENGINE=INNODB;
+INSERT INTO t1 VALUES (123);
+
+CREATE TABLE t2 (c2 INT, PRIMARY KEY (c2)) ENGINE=INNODB;
+INSERT INTO t2 VALUES (456);
+
+-- connect (con1,localhost,root,,)
+-- connect (con2,localhost,root,,)
+
+-- connection con1
+BEGIN;
+SELECT * FROM t1 FOR UPDATE;
+
+-- connection con2
+BEGIN;
+SELECT * FROM t2 FOR UPDATE;
+
+-- connection con1
+-- send
+SELECT * FROM t2 FOR UPDATE;
+
+-- connection con2
+let $wait_condition=
+SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST
+WHERE state = 'Sending data' AND info = 'SELECT * FROM t2 FOR UPDATE';
+-- source include/wait_condition.inc
+-- error ER_LOCK_DEADLOCK
+SELECT * FROM t1 FOR UPDATE;
+
+-- connection default
+
+-- disconnect con1
+-- disconnect con2
+
+DROP TABLE t2;
+DROP TABLE t1;
+
+SET GLOBAL innodb_print_all_deadlocks=default;

storage/innobase/handler/ha_innodb.cc

@@ -11691,6 +11691,11 @@ static MYSQL_SYSVAR_UINT(limit_optimistic_insert_debug,
   NULL, NULL, 0, 0, UINT_MAX32, 0);
 #endif /* UNIV_DEBUG */
 
+static MYSQL_SYSVAR_BOOL(print_all_deadlocks, srv_print_all_deadlocks,
+  PLUGIN_VAR_OPCMDARG,
+  "Print all deadlocks to MySQL error log (off by default)",
+  NULL, NULL, FALSE);
+
 static struct st_mysql_sys_var* innobase_system_variables[]= {
   MYSQL_SYSVAR(additional_mem_pool_size),
   MYSQL_SYSVAR(autoextend_increment),
@@ -11764,6 +11769,7 @@ static struct st_mysql_sys_var* innobase_system_variables[]= {
   MYSQL_SYSVAR(trx_rseg_n_slots_debug),
   MYSQL_SYSVAR(limit_optimistic_insert_debug),
 #endif /* UNIV_DEBUG */
+  MYSQL_SYSVAR(print_all_deadlocks),
   NULL
 };
 

storage/innobase/include/srv0srv.h

@@ -333,6 +333,9 @@ extern ulint srv_buf_pool_flushed;
 reading of a disk page */
 extern ulint srv_buf_pool_reads;
 
+/** print all user-level transactions deadlocks to mysqld stderr */
+extern my_bool srv_print_all_deadlocks;
+
 /** Status variables to be passed to MySQL */
 typedef struct export_var_struct export_struc;
 

storage/innobase/lock/lock0lock.c

@@ -3261,6 +3261,80 @@ lock_rec_restore_from_page_infimum(
 
 /*=========== DEADLOCK CHECKING ======================================*/
 
+/*********************************************************************//**
+rewind(3) the file used for storing the latest detected deadlock and
+print a heading message to stderr if printing of all deadlocks to stderr
+is enabled. */
+UNIV_INLINE
+void
+lock_deadlock_start_print()
+/*=======================*/
+{
+	rewind(lock_latest_err_file);
+	ut_print_timestamp(lock_latest_err_file);
+
+	if (srv_print_all_deadlocks) {
+		fprintf(stderr, "InnoDB: transactions deadlock detected, "
+			"dumping detailed information.\n");
+		ut_print_timestamp(stderr);
+	}
+}
+
+/*********************************************************************//**
+Print a message to the deadlock file and possibly to stderr. */
+UNIV_INLINE
+void
+lock_deadlock_fputs(
+/*================*/
+	const char*	msg)	/*!< in: message to print */
+{
+	fputs(msg, lock_latest_err_file);
+
+	if (srv_print_all_deadlocks) {
+		fputs(msg, stderr);
+	}
+}
+
+/*********************************************************************//**
+Print transaction data to the deadlock file and possibly to stderr. */
+UNIV_INLINE
+void
+lock_deadlock_trx_print(
+/*====================*/
+	trx_t*	trx,		/*!< in: transaction */
+	ulint	max_query_len)	/*!< in: max query length to print, or 0 to
+				use the default max length */
+{
+	trx_print(lock_latest_err_file, trx, max_query_len);
+
+	if (srv_print_all_deadlocks) {
+		trx_print(stderr, trx, max_query_len);
+	}
+}
+
+/*********************************************************************//**
+Print lock data to the deadlock file and possibly to stderr. */
+UNIV_INLINE
+void
+lock_deadlock_lock_print(
+/*=====================*/
+	const lock_t*	lock)	/*!< in: record or table type lock */
+{
+	if (lock_get_type_low(lock) == LOCK_REC) {
+		lock_rec_print(lock_latest_err_file, lock);
+
+		if (srv_print_all_deadlocks) {
+			lock_rec_print(stderr, lock);
+		}
+	} else {
+		lock_table_print(lock_latest_err_file, lock);
+
+		if (srv_print_all_deadlocks) {
+			lock_table_print(stderr, lock);
+		}
+	}
+}
+
 /********************************************************************//**
 Checks if a lock request results in a deadlock.
 @return TRUE if a deadlock was detected and we chose trx as a victim;
@@ -3304,30 +3378,25 @@ retry:
 		/* If the lock search exceeds the max step
 		or the max depth, the current trx will be
 		the victim. Print its information. */
-		rewind(lock_latest_err_file);
-		ut_print_timestamp(lock_latest_err_file);
+		lock_deadlock_start_print();
 
-		fputs("TOO DEEP OR LONG SEARCH IN THE LOCK TABLE"
-		      " WAITS-FOR GRAPH, WE WILL ROLL BACK"
-		      " FOLLOWING TRANSACTION \n",
-		      lock_latest_err_file);
+		lock_deadlock_fputs(
+			"TOO DEEP OR LONG SEARCH IN THE LOCK TABLE"
+			" WAITS-FOR GRAPH, WE WILL ROLL BACK"
+			" FOLLOWING TRANSACTION \n\n"
+			"*** TRANSACTION:\n");
 
-		fputs("\n*** TRANSACTION:\n", lock_latest_err_file);
-		      trx_print(lock_latest_err_file, trx, 3000);
+		lock_deadlock_trx_print(trx, 3000);
 
-		fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n",
-		      lock_latest_err_file);
+		lock_deadlock_fputs(
+			"*** WAITING FOR THIS LOCK TO BE GRANTED:\n");
+
+		lock_deadlock_lock_print(lock);
 
-		if (lock_get_type(lock) == LOCK_REC) {
-			lock_rec_print(lock_latest_err_file, lock);
-		} else {
-			lock_table_print(lock_latest_err_file, lock);
-		}
 		break;
 
 	case LOCK_VICTIM_IS_START:
-		fputs("*** WE ROLL BACK TRANSACTION (2)\n",
-		      lock_latest_err_file);
+		lock_deadlock_fputs("*** WE ROLL BACK TRANSACTION (2)\n");
 		break;
 
 	default:
@@ -3442,45 +3511,33 @@ lock_deadlock_recursive(
 				point: a deadlock detected; or we have
 				searched the waits-for graph too long */
 
-				FILE*	ef = lock_latest_err_file;
+				lock_deadlock_start_print();
 
-				rewind(ef);
-				ut_print_timestamp(ef);
+				lock_deadlock_fputs("\n*** (1) TRANSACTION:\n");
 
-				fputs("\n*** (1) TRANSACTION:\n", ef);
+				lock_deadlock_trx_print(wait_lock->trx, 3000);
 
-				trx_print(ef, wait_lock->trx, 3000);
+				lock_deadlock_fputs(
+					"*** (1) WAITING FOR THIS LOCK"
+					" TO BE GRANTED:\n");
 
-				fputs("*** (1) WAITING FOR THIS LOCK"
-				      " TO BE GRANTED:\n", ef);
+				lock_deadlock_lock_print(wait_lock);
 
-				if (lock_get_type_low(wait_lock) == LOCK_REC) {
-					lock_rec_print(ef, wait_lock);
-				} else {
-					lock_table_print(ef, wait_lock);
-				}
+				lock_deadlock_fputs("*** (2) TRANSACTION:\n");
 
-				fputs("*** (2) TRANSACTION:\n", ef);
+				lock_deadlock_trx_print(lock->trx, 3000);
 
-				trx_print(ef, lock->trx, 3000);
+				lock_deadlock_fputs(
+					"*** (2) HOLDS THE LOCK(S):\n");
 
-				fputs("*** (2) HOLDS THE LOCK(S):\n", ef);
+				lock_deadlock_lock_print(lock);
 
-				if (lock_get_type_low(lock) == LOCK_REC) {
-					lock_rec_print(ef, lock);
-				} else {
-					lock_table_print(ef, lock);
-				}
+				lock_deadlock_fputs(
+					"*** (2) WAITING FOR THIS LOCK"
+					" TO BE GRANTED:\n");
 
-				fputs("*** (2) WAITING FOR THIS LOCK"
-				      " TO BE GRANTED:\n", ef);
+				lock_deadlock_lock_print(start->wait_lock);
 
-				if (lock_get_type_low(start->wait_lock)
-				    == LOCK_REC) {
-					lock_rec_print(ef, start->wait_lock);
-				} else {
-					lock_table_print(ef, start->wait_lock);
-				}
 #ifdef UNIV_DEBUG
 				if (lock_print_waits) {
 					fputs("Deadlock detected\n",
@@ -3503,8 +3560,8 @@ lock_deadlock_recursive(
 				as a victim to try to avoid deadlocking our
 				recursion starting point transaction */
 
-				fputs("*** WE ROLL BACK TRANSACTION (1)\n",
-				      ef);
+				lock_deadlock_fputs(
+					"*** WE ROLL BACK TRANSACTION (1)\n");
 
 				wait_lock->trx->was_chosen_as_deadlock_victim
 					= TRUE;

storage/innobase/srv/srv0srv.c

@@ -356,6 +356,9 @@ UNIV_INTERN lint	srv_conc_n_threads	= 0;
 InnoDB */
 UNIV_INTERN ulint	srv_conc_n_waiting_threads = 0;
 
+/* print all user-level transactions deadlocks to mysqld stderr */
+UNIV_INTERN my_bool	srv_print_all_deadlocks = FALSE;
+
 typedef struct srv_conc_slot_struct	srv_conc_slot_t;
 struct srv_conc_slot_struct{
 	os_event_t			event;		/*!< event to wait */