1 files changed, 123 insertions, 113 deletions

diff --git a/storage/xtradb/lock/lock0lock.cc b/storage/xtradb/lock/lock0lock.cc
index 061813cd8ab..b0ab3e7a540 100644
--- a/storage/xtradb/lock/lock0lock.cc
+++ b/storage/xtradb/lock/lock0lock.cc
@@ -383,6 +383,20 @@ struct lock_stack_t {
 	ulint		heap_no;		/*!< heap number if rec lock */
 };
 
+/** Pretty-print a table lock.
+@param[in,out]	file	output stream
+@param[in]	lock	table lock
+@param[in]	now	current time */
+static void lock_table_print(FILE* file, const lock_t* lock, time_t now);
+
+/** Pretty-print a record lock.
+@param[in,out]	file	output stream
+@param[in]	lock	record lock
+@param[in]	now	current time
+@param[in,out]	mtr	mini-transaction */
+static void lock_rec_print(FILE* file, const lock_t* lock, time_t now,
+			   mtr_t* mtr = NULL);
+
 /*********************************************************************//**
 Checks if a waiting record lock request still has to wait in a queue.
 @return lock that is causing the wait */
@@ -466,20 +480,18 @@ UNIV_INTERN ibool	lock_deadlock_found = FALSE;
 /** Only created if !srv_read_only_mode */
 static FILE*		lock_latest_err_file;
 
-/********************************************************************//**
-Checks if a joining lock request results in a deadlock. If a deadlock is
+/** Check if a joining lock request results in a deadlock. If a deadlock is
 found this function will resolve the dadlock by choosing a victim transaction
-and rolling it back. It will attempt to resolve all deadlocks. The returned
-transaction id will be the joining transaction id or 0 if some other
-transaction was chosen as a victim and rolled back or no deadlock found.
-
-@return id of transaction chosen as victim or 0 */
-static
-trx_id_t
-lock_deadlock_check_and_resolve(
-/*===========================*/
-	const lock_t*	lock,	/*!< in: lock the transaction is requesting */
-	const trx_t*	trx);	/*!< in: transaction */
+and rolling it back. It will attempt to resolve all deadlocks.
+@param[in]	trx	joining transaction
+@param[in]	lock	the requested lock
+@param[in]	now	current time
+@return trx->id of the victim transaction
+@retval 0	if some other transaction was chosen as a victim and
+rolled back, or no deadlock was found. */
+static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx,
+						const lock_t* lock,
+						time_t now);
 
 /*********************************************************************//**
 Gets the nth bit of a record lock.
@@ -1147,12 +1159,11 @@ lock_rec_has_to_wait(
 		   thread, we need to look at trx ordering and lock types */
 		if (wsrep_thd_is_BF(trx->mysql_thd, FALSE)         &&
 		    wsrep_thd_is_BF(lock2->trx->mysql_thd, TRUE)) {
-
 			if (wsrep_debug) {
 				fprintf(stderr,
 					"BF-BF lock conflict, locking: %lu\n",
 					for_locking);
-				lock_rec_print(stderr, lock2);
+				lock_rec_print(stderr, lock2, time(NULL));
 			}
 
 			if (wsrep_trx_order_before(trx->mysql_thd,
@@ -1171,7 +1182,8 @@ lock_rec_has_to_wait(
 						"conflicts states: my %d locked %d\n",
 						wsrep_thd_conflict_state(trx->mysql_thd, FALSE),
 						wsrep_thd_conflict_state(lock2->trx->mysql_thd, FALSE) );
-					lock_rec_print(stderr, lock2);
+					lock_rec_print(stderr, lock2,
+						       time(NULL));
 					if (for_locking) return FALSE;
 					//abort();
 				}
@@ -1797,10 +1809,12 @@ wsrep_kill_victim(
 				fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n",
 				      stderr);
 
+				time_t now = time(NULL);
+
 				if (lock_get_type(lock) == LOCK_REC) {
-					lock_rec_print(stderr, lock);
+					lock_rec_print(stderr, lock, now);
 				} else {
-					lock_table_print(stderr, lock);
+					lock_table_print(stderr, lock, now);
 				}
 			}
 
@@ -2055,16 +2069,20 @@ wsrep_print_wait_locks(
 {
 	if (wsrep_debug &&  c_lock->trx->lock.wait_lock != c_lock) {
 		fprintf(stderr, "WSREP: c_lock != wait lock\n");
+		time_t now = time(NULL);
+
 		if (lock_get_type_low(c_lock) & LOCK_TABLE) {
-			lock_table_print(stderr, c_lock);
+			lock_table_print(stderr, c_lock, now);
 		} else {
-			lock_rec_print(stderr, c_lock);
+			lock_rec_print(stderr, c_lock, now);
 		}
 
 		if (lock_get_type_low(c_lock->trx->lock.wait_lock) & LOCK_TABLE) {
-			lock_table_print(stderr, c_lock->trx->lock.wait_lock);
+			lock_table_print(stderr, c_lock->trx->lock.wait_lock,
+					 now);
 		} else {
-			lock_rec_print(stderr, c_lock->trx->lock.wait_lock);
+			lock_rec_print(stderr, c_lock->trx->lock.wait_lock,
+				       now);
 		}
 	}
 }
@@ -2503,7 +2521,8 @@ lock_rec_enqueue_waiting(
 
 	trx_mutex_exit(trx);
 
-	victim_trx_id = lock_deadlock_check_and_resolve(lock, trx);
+	const time_t now = time(NULL);
+	victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now);
 
 	trx_mutex_enter(trx);
 
@@ -2527,7 +2546,7 @@ lock_rec_enqueue_waiting(
 		trx->lock.que_state = TRX_QUE_LOCK_WAIT;
 
 		trx->lock.was_chosen_as_deadlock_victim = FALSE;
-		trx->lock.wait_started = ut_time();
+		trx->lock.wait_started = now;
 
 		if (UNIV_UNLIKELY(trx->take_stats)) {
 			trx->lock_que_wait_nstarted = my_interval_timer();
@@ -2672,7 +2691,8 @@ lock_rec_add_to_queue(
 						"BF skipping wait: "
 						TRX_ID_FMT "\n",
 						trx->id);
-					lock_rec_print(stderr, lock);
+					lock_rec_print(stderr, lock,
+						       time(NULL));
 				}
 		  } else
 #endif
@@ -2991,13 +3011,14 @@ lock_rec_has_to_wait_in_queue(
 			if (wsrep_thd_is_BF(wait_lock->trx->mysql_thd, FALSE) &&
 			    wsrep_thd_is_BF(lock->trx->mysql_thd, TRUE)) {
 				if (wsrep_debug) {
+					time_t now = time(NULL);
 					fprintf(stderr,
 						"BF-BF lock conflict " TRX_ID_FMT
 						" : " TRX_ID_FMT "\n",
 						wait_lock->trx->id,
 						lock->trx->id);
-					lock_rec_print(stderr, wait_lock);
-					lock_rec_print(stderr, lock);
+					lock_rec_print(stderr, wait_lock, now);
+					lock_rec_print(stderr, lock, now);
 				}
 				/* don't wait for another BF lock */
 				continue;
@@ -4328,28 +4349,26 @@ lock_deadlock_trx_print(
 	mutex_exit(&trx_sys->mutex);
 }
 
-/*********************************************************************//**
-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 */
+/** Print lock data to the deadlock file and possibly to stderr.
+@param[in]	lock	record or table lock
+@param[in]	now	current time */
+static void lock_deadlock_lock_print(const lock_t* lock, time_t now)
 {
 	ut_ad(lock_mutex_own());
 	ut_ad(!srv_read_only_mode);
 
 	if (lock_get_type_low(lock) == LOCK_REC) {
-		lock_rec_print(lock_latest_err_file, lock);
+		mtr_t mtr;
+		lock_rec_print(lock_latest_err_file, lock, now, &mtr);
 
 		if (srv_print_all_deadlocks) {
-			lock_rec_print(stderr, lock);
+			lock_rec_print(stderr, lock, now, &mtr);
 		}
 	} else {
-		lock_table_print(lock_latest_err_file, lock);
+		lock_table_print(lock_latest_err_file, lock, now);
 
 		if (srv_print_all_deadlocks) {
-			lock_table_print(stderr, lock);
+			lock_table_print(stderr, lock, now);
 		}
 	}
 }
@@ -4462,6 +4481,8 @@ lock_deadlock_notify(
 	ut_ad(lock_mutex_own());
 	ut_ad(!srv_read_only_mode);
 
+	const time_t now = time(NULL);
+
 	lock_deadlock_start_print();
 
 	lock_deadlock_fputs("\n*** (1) TRANSACTION:\n");
@@ -4470,7 +4491,7 @@ lock_deadlock_notify(
 
 	lock_deadlock_fputs("*** (1) WAITING FOR THIS LOCK TO BE GRANTED:\n");
 
-	lock_deadlock_lock_print(ctx->wait_lock);
+	lock_deadlock_lock_print(ctx->wait_lock, now);
 
 	lock_deadlock_fputs("*** (2) TRANSACTION:\n");
 
@@ -4478,7 +4499,7 @@ lock_deadlock_notify(
 
 	lock_deadlock_fputs("*** (2) HOLDS THE LOCK(S):\n");
 
-	lock_deadlock_lock_print(lock);
+	lock_deadlock_lock_print(lock, now);
 
 	/* It is possible that the joining transaction was granted its
 	lock when we rolled back some other waiting transaction. */
@@ -4487,7 +4508,7 @@ lock_deadlock_notify(
 		lock_deadlock_fputs(
 			"*** (2) WAITING FOR THIS LOCK TO BE GRANTED:\n");
 
-		lock_deadlock_lock_print(ctx->start->lock.wait_lock);
+		lock_deadlock_lock_print(ctx->start->lock.wait_lock, now);
 	}
 
 #ifdef UNIV_DEBUG
@@ -4736,14 +4757,12 @@ lock_deadlock_search(
 	return(0);
 }
 
-/********************************************************************//**
-Print info about transaction that was rolled back. */
-static
-void
-lock_deadlock_joining_trx_print(
-/*============================*/
-	const trx_t*	trx,		/*!< in: transaction rolled back */
-	const lock_t*	lock)		/*!< in: lock trx wants */
+/** Print info about transaction that was rolled back.
+@param[in]	trx	victim transaction
+@param[in]	lock	the requested lock
+@param[in]	now	current time */
+static void lock_deadlock_joining_trx_print(const trx_t* trx,
+					    const lock_t* lock, time_t now)
 {
 	ut_ad(lock_mutex_own());
 	ut_ad(!srv_read_only_mode);
@@ -4763,7 +4782,7 @@ lock_deadlock_joining_trx_print(
 
 	lock_deadlock_fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n");
 
-	lock_deadlock_lock_print(lock);
+	lock_deadlock_lock_print(lock, now);
 }
 
 /********************************************************************//**
@@ -4833,20 +4852,17 @@ lock_report_waiters_to_mysql(
 }
 
 
-/********************************************************************//**
-Checks if a joining lock request results in a deadlock. If a deadlock is
+/** Check if a joining lock request results in a deadlock. If a deadlock is
 found this function will resolve the dadlock by choosing a victim transaction
-and rolling it back. It will attempt to resolve all deadlocks. The returned
-transaction id will be the joining transaction id or 0 if some other
-transaction was chosen as a victim and rolled back or no deadlock found.
-
-@return id of transaction chosen as victim or 0 */
-static
-trx_id_t
-lock_deadlock_check_and_resolve(
-/*============================*/
-	const lock_t*	lock,	/*!< in: lock the transaction is requesting */
-	const trx_t*	trx)	/*!< in: transaction */
+and rolling it back. It will attempt to resolve all deadlocks.
+@param[in]	trx	joining transaction
+@param[in]	lock	the requested lock
+@param[in]	now	current time
+@return trx->id of the victim transaction
+@retval 0	if some other transaction was chosen as a victim and
+rolled back, or no deadlock was found. */
+static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx,
+						const lock_t* lock, time_t now)
 {
 	trx_id_t		victim_trx_id;
 	struct thd_wait_reports	waitee_buf;
@@ -4898,18 +4914,12 @@ lock_deadlock_check_and_resolve(
 			ut_a(victim_trx_id == trx->id);
 
 #ifdef WITH_WSREP
-			if (!wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE))
-			{
+			if (wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE)); else
 #endif /* WITH_WSREP */
-				if (!srv_read_only_mode) {
-					lock_deadlock_joining_trx_print(trx, lock);
-				}
-#ifdef WITH_WSREP
-			} else {
-			  /* BF processor */;
+			if (!srv_read_only_mode) {
+				lock_deadlock_joining_trx_print(trx, lock,
+								now);
 			}
-#endif /* WITH_WSREP */
-
 		} else if (victim_trx_id != 0 && victim_trx_id != trx->id) {
 
 			ut_ad(victim_trx_id == ctx.wait_lock->trx->id);
@@ -5255,7 +5265,9 @@ lock_table_enqueue_waiting(
 
 	trx_mutex_exit(trx);
 
-	victim_trx_id = lock_deadlock_check_and_resolve(lock, trx);
+	const time_t now = time(NULL);
+
+	victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now);
 
 	trx_mutex_enter(trx);
 
@@ -5277,7 +5289,7 @@ lock_table_enqueue_waiting(
 
 	trx->lock.que_state = TRX_QUE_LOCK_WAIT;
 
-	trx->lock.wait_started = ut_time();
+	trx->lock.wait_started = now;
 	trx->lock.was_chosen_as_deadlock_victim = FALSE;
 	trx->n_table_lock_waits++;
 
@@ -6029,14 +6041,11 @@ lock_remove_all_on_table(
 
 /*===================== VALIDATION AND DEBUGGING  ====================*/
 
-/*********************************************************************//**
-Prints info of a table lock. */
-UNIV_INTERN
-void
-lock_table_print(
-/*=============*/
-	FILE*		file,	/*!< in: file where to print */
-	const lock_t*	lock)	/*!< in: table type lock */
+/** Pretty-print a table lock.
+@param[in,out]	file	output stream
+@param[in]	lock	table lock
+@param[in]	now	current time */
+static void lock_table_print(FILE* file, const lock_t* lock, time_t now)
 {
 	ut_ad(lock_mutex_own());
 	ut_a(lock_get_type_low(lock) == LOCK_TABLE);
@@ -6066,30 +6075,22 @@ lock_table_print(
 	}
 
 	fprintf(file, " lock hold time %lu wait time before grant %lu ",
-		(ulint)difftime(ut_time(), lock->requested_time),
+		(ulint)difftime(now, lock->requested_time),
 		lock->wait_time);
 
 	putc('\n', file);
 }
 
-/*********************************************************************//**
-Prints info of a record lock. */
-UNIV_INTERN
-void
-lock_rec_print(
-/*===========*/
-	FILE*		file,	/*!< in: file where to print */
-	const lock_t*	lock)	/*!< in: record type lock */
+/** Pretty-print a record lock.
+@param[in,out]	file	output stream
+@param[in]	lock	record lock
+@param[in]	now	current time
+@param[in,out]	mtr	mini-transaction */
+static void lock_rec_print(FILE* file, const lock_t* lock, time_t now,
+			   mtr_t* mtr)
 {
-	const buf_block_t*	block;
 	ulint			space;
 	ulint			page_no;
-	ulint			i;
-	mtr_t			mtr;
-	mem_heap_t*		heap		= NULL;
-	ulint			offsets_[REC_OFFS_NORMAL_SIZE];
-	ulint*			offsets		= offsets_;
-	rec_offs_init(offsets_);
 
 	ut_ad(lock_mutex_own());
 	ut_a(lock_get_type_low(lock) == LOCK_REC);
@@ -6134,18 +6135,25 @@ lock_rec_print(
 		fputs(" waiting", file);
 	}
 
-	mtr_start(&mtr);
-
 	fprintf(file, " lock hold time %lu wait time before grant %lu ",
-		(ulint)difftime(ut_time(), lock->requested_time),
+		(ulint)difftime(now, lock->requested_time),
 		lock->wait_time);
 
 	putc('\n', file);
 
-	if ( srv_show_verbose_locks ) {
-	block = buf_page_try_get(space, page_no, &mtr);
+	if (!srv_show_verbose_locks || !mtr) {
+		return;
+	}
 
-	for (i = 0; i < lock_rec_get_n_bits(lock); ++i) {
+	mem_heap_t*		heap		= NULL;
+	ulint			offsets_[REC_OFFS_NORMAL_SIZE];
+	ulint*			offsets		= offsets_;
+	rec_offs_init(offsets_);
+
+	mtr_start(mtr);
+	const buf_block_t* block = buf_page_try_get(space, page_no, mtr);
+
+	for (ulint i = 0; i < lock_rec_get_n_bits(lock); ++i) {
 
 		if (!lock_rec_get_nth_bit(lock, i)) {
 			continue;
@@ -6169,9 +6177,8 @@ lock_rec_print(
 
 		putc('\n', file);
 	}
-	}
 
-	mtr_commit(&mtr);
+	mtr_commit(mtr);
 	if (UNIV_LIKELY_NULL(heap)) {
 		mem_heap_free(heap);
 	}
@@ -6327,6 +6334,8 @@ lock_print_info_all_transactions(
 
 	ut_ad(lock_mutex_own());
 
+	const time_t now = time(NULL);
+
 	mutex_enter(&trx_sys->mutex);
 
 	/* First print info on non-active transactions */
@@ -6413,13 +6422,14 @@ loop:
 			fprintf(file,
 				"------- TRX HAS BEEN WAITING %lu SEC"
 				" FOR THIS LOCK TO BE GRANTED:\n",
-				(ulong) difftime(ut_time(),
-						 trx->lock.wait_started));
+				(ulong) difftime(now, trx->lock.wait_started));
 
 			if (lock_get_type_low(trx->lock.wait_lock) == LOCK_REC) {
-				lock_rec_print(file, trx->lock.wait_lock);
+				lock_rec_print(file, trx->lock.wait_lock, now,
+					       &mtr);
 			} else {
-				lock_table_print(file, trx->lock.wait_lock);
+				lock_table_print(file, trx->lock.wait_lock,
+						 now);
 			}
 
 			fputs("------------------\n", file);
@@ -6508,11 +6518,11 @@ loop:
 		}
 
 print_rec:
-		lock_rec_print(file, lock);
+		lock_rec_print(file, lock, now, &mtr);
 	} else {
 		ut_ad(lock_get_type_low(lock) & LOCK_TABLE);
 
-		lock_table_print(file, lock);
+		lock_table_print(file, lock, now);
 	}
 
 	load_page_first = TRUE;