MDEV-12837: WSREP: BF lock wait long

Problem was a merge error from MySQL wsrep i.e. Galera.

wsrep_on_check
	New check function. Galera can't be enabled
	if innodb-lock-schedule-algorithm=VATS.

innobase_kill_query
	In Galera async kill we could own lock mutex.

innobase_init
	If Variance-Aware-Transaction-Sheduling Algorithm (VATS) is
	used on Galera we fall back to First-Come-First-Served (FCFS)
	with notice to user.

Changed innodb-lock-schedule-algorithm as read-only parameter
as it was designed to be.

lock_reset_lock_and_trx_wait
	Use ib::hex() to print out transaction ID.

lock_rec_other_has_expl_req,
lock_rec_other_has_conflicting,
RecLock::add_to_waitq
lock_rec_lock_slow
lock_table_other_has_incompatible
lock_rec_insert_check_and_lock
lock_prdt_other_has_conflicting

	Change pointer to conflicting lock to normal pointer as this
	pointer contents could be changed later.

RecLock::create
	Conclicting lock pointer is moved to last parameter with
	default value NULL. This conflicting transaction could
	be selected as victim in Galera if requesting transaction
	is BF (brute force) transaction. In this case contents
	of conflicting lock pointer will be changed. Use ib::hex() to print
	transaction ids.

8 files changed, 153 insertions, 86 deletions

diff --git a/sql/sys_vars.cc b/sql/sys_vars.cc
index a32bc3fce8e..d53276d7c24 100644
--- a/sql/sys_vars.cc
+++ b/sql/sys_vars.cc
@@ -5005,7 +5005,8 @@ static Sys_var_mybool Sys_wsrep_on (
        "wsrep_on", "To enable wsrep replication ",
        SESSION_VAR(wsrep_on), 
        CMD_LINE(OPT_ARG), DEFAULT(FALSE),
-       NO_MUTEX_GUARD, NOT_IN_BINLOG, ON_CHECK(0),
+       NO_MUTEX_GUARD, NOT_IN_BINLOG,
+       ON_CHECK(wsrep_on_check),
        ON_UPDATE(wsrep_on_update));
 
 static Sys_var_charptr Sys_wsrep_start_position (
diff --git a/sql/wsrep_var.cc b/sql/wsrep_var.cc
index 5b001ca2922..3c90f03a5fb 100644
--- a/sql/wsrep_var.cc
+++ b/sql/wsrep_var.cc
@@ -42,12 +42,28 @@ int wsrep_init_vars()
   return 0;
 }
 
+extern ulong innodb_lock_schedule_algorithm;
+
 bool wsrep_on_update (sys_var *self, THD* thd, enum_var_type var_type)
 {
   if (var_type == OPT_GLOBAL) {
     // FIXME: this variable probably should be changed only per session
     thd->variables.wsrep_on = global_system_variables.wsrep_on;
   }
+
+  return false;
+}
+
+bool wsrep_on_check(sys_var *self, THD* thd, set_var* var)
+{
+  bool new_wsrep_on= (bool)var->save_result.ulonglong_value;
+
+  if (new_wsrep_on && innodb_lock_schedule_algorithm != 0) {
+    my_message(ER_WRONG_ARGUMENTS, " WSREP (galera) can't be enabled "
+	    "if innodb_lock_schedule_algorithm=VATS. Please configure"
+	    " innodb_lock_schedule_algorithm=FCFS and restart.", MYF(0));
+    return true;
+  }
   return false;
 }
 
diff --git a/sql/wsrep_var.h b/sql/wsrep_var.h
index dde59d1503f..b9051b29843 100644
--- a/sql/wsrep_var.h
+++ b/sql/wsrep_var.h
@@ -41,7 +41,8 @@ int wsrep_init_vars();
 #define DEFAULT_ARGS (THD* thd, enum_var_type var_type)
 #define INIT_ARGS    (const char* opt)
 
-extern bool wsrep_causal_reads_update         UPDATE_ARGS;
+extern bool wsrep_causal_reads_update        UPDATE_ARGS;
+extern bool wsrep_on_check                   CHECK_ARGS;
 extern bool wsrep_on_update                  UPDATE_ARGS;
 extern bool wsrep_sync_wait_update           UPDATE_ARGS;
 extern bool wsrep_start_position_check       CHECK_ARGS;
diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index e02fb953a48..a87ab677d04 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -3862,6 +3862,16 @@ innobase_init(
 		goto error;
 	}
 
+#ifdef WITH_WSREP
+	/* Currently, Galera does not support VATS lock schedule algorithm. */
+	if (innodb_lock_schedule_algorithm == INNODB_LOCK_SCHEDULE_ALGORITHM_VATS
+	    && global_system_variables.wsrep_on) {
+		ib::info() << "In Galera environment Variance-Aware-Transaction-Sheduling Algorithm"
+			   " is not supported. Falling back to First-Come-First-Served order. ";
+		innodb_lock_schedule_algorithm = INNODB_LOCK_SCHEDULE_ALGORITHM_FCFS;
+	}
+#endif /* WITH_WSREP */
+
 #ifndef HAVE_LZ4
 	if (innodb_compression_algorithm == PAGE_LZ4_ALGORITHM) {
 		sql_print_error("InnoDB: innodb_compression_algorithm = %lu unsupported.\n"
@@ -5351,7 +5361,7 @@ innobase_kill_query(
 				wsrep_thd_is_BF(current_thd, FALSE));
 		}
 
-		if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE)) {
+		if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE) && trx->abort_type != TRX_WSREP_ABORT) {
 			lock_mutex_enter();
 			lock_mutex_taken = true;
 		}
@@ -20863,7 +20873,7 @@ static MYSQL_SYSVAR_ULONG(doublewrite_batch_size, srv_doublewrite_batch_size,
 #endif /* defined UNIV_DEBUG || defined UNIV_PERF_DEBUG */
 
 static MYSQL_SYSVAR_ENUM(lock_schedule_algorithm, innodb_lock_schedule_algorithm,
-  PLUGIN_VAR_RQCMDARG,
+  PLUGIN_VAR_RQCMDARG | PLUGIN_VAR_READONLY,
   "The algorithm Innodb uses for deciding which locks to grant next when"
   " a lock is released. Possible values are"
   " FCFS"
diff --git a/storage/innobase/include/lock0priv.h b/storage/innobase/include/lock0priv.h
index 6bb75817ad6..185779e476f 100644
--- a/storage/innobase/include/lock0priv.h
+++ b/storage/innobase/include/lock0priv.h
@@ -721,7 +721,7 @@ public:
 		as a victim, and we got the lock immediately: no need to
 		wait then */
 	dberr_t add_to_waitq(
-		const lock_t*	wait_for,
+		lock_t*	wait_for,
 		const lock_prdt_t*
 				prdt = NULL);
 
@@ -731,21 +731,22 @@ public:
 	@param[in] owns_trx_mutex	true if caller owns the trx_t::mutex
 	@param[in] add_to_hash		add the lock to hash table
 	@param[in] prdt			Predicate lock (optional)
+	@param[in,out] c_lock		Conflicting lock request or NULL
+					in Galera conflicting lock is selected
+					as deadlock victim if requester
+					is BF transaction.
 	@return new lock instance */
 	lock_t* create(
 		trx_t*		trx,
 		bool		owns_trx_mutex,
 		bool		add_to_hash,
 		const lock_prdt_t*
-				prdt = NULL);
+				prdt = NULL
+#ifdef WITH_WSREP
+		,lock_t*	c_lock = NULL
+#endif /* WITH_WSREP */
+	);
 
-	lock_t* create(
-		lock_t* const	c_lock,
-		trx_t*		trx,
-		bool		owns_trx_mutex,
-		bool		add_to_hash,
-		const lock_prdt_t*
-				prdt = NULL);
 	/**
 	Check of the lock is on m_rec_id.
 	@param[in] lock			Lock to compare with
diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc
index d9ac953d2e8..7a1afec820c 100644
--- a/storage/innobase/lock/lock0lock.cc
+++ b/storage/innobase/lock/lock0lock.cc
@@ -811,13 +811,18 @@ lock_reset_lock_and_trx_wait(
 		}
 
 		ib::error() <<
-			"Trx id " << lock->trx->id
-				  << " is waiting a lock in statement "
-				  << (stmt ? stmt : "NULL")
-				  << " for this trx id " << trx_id
-				  << " and statement "
-				  << (stmt2 ? stmt2 : "NULL")
-				  << "wait_lock " << lock->trx->lock.wait_lock;
+			"Trx id " << ib::hex(lock->trx->id)
+				  << " is waiting a lock "
+				  << " for this trx id " << ib::hex(trx_id)
+				  << " wait_lock " << lock->trx->lock.wait_lock;
+		if (stmt) {
+			ib::info() << " SQL1: " << stmt;
+		}
+
+		if (stmt2) {
+			ib::info() << " SQL2: " << stmt2;
+		}
+
 		ut_ad(0);
 	}
 
@@ -1316,7 +1321,7 @@ lock_rec_has_expl(
 Checks if some other transaction has a lock request in the queue.
 @return lock or NULL */
 static
-const lock_t*
+lock_t*
 lock_rec_other_has_expl_req(
 /*========================*/
 	lock_mode		mode,	/*!< in: LOCK_S or LOCK_X */
@@ -1339,10 +1344,10 @@ lock_rec_other_has_expl_req(
 		return(NULL);
 	}
 
-	for (const lock_t* lock = lock_rec_get_first(lock_sys->rec_hash,
+	for (lock_t* lock = lock_rec_get_first(lock_sys->rec_hash,
 						     block, heap_no);
 	     lock != NULL;
-	     lock = lock_rec_get_next_const(heap_no, lock)) {
+	     lock = lock_rec_get_next(heap_no, lock)) {
 
 		if (lock->trx != trx
 		    && !lock_rec_get_gap(lock)
@@ -1431,7 +1436,7 @@ Checks if some other transaction has a conflicting explicit lock request
 in the queue, so that we have to wait.
 @return lock or NULL */
 static
-const lock_t*
+lock_t*
 lock_rec_other_has_conflicting(
 /*===========================*/
 	ulint			mode,	/*!< in: LOCK_S or LOCK_X,
@@ -1443,7 +1448,7 @@ lock_rec_other_has_conflicting(
 	ulint			heap_no,/*!< in: heap number of the record */
 	const trx_t*		trx)	/*!< in: our transaction */
 {
-	const lock_t*		lock;
+	lock_t*		lock;
 
 	ut_ad(lock_mutex_own());
 
@@ -1451,13 +1456,16 @@ lock_rec_other_has_conflicting(
 
 	for (lock = lock_rec_get_first(lock_sys->rec_hash, block, heap_no);
 	     lock != NULL;
-	     lock = lock_rec_get_next_const(heap_no, lock)) {
+	     lock = lock_rec_get_next(heap_no, lock)) {
 
 		if (lock_rec_has_to_wait(true, trx, mode, lock, is_supremum)) {
 #ifdef WITH_WSREP
 			if (wsrep_on_trx(trx)) {
 				trx_mutex_enter(lock->trx);
-				wsrep_kill_victim((trx_t *)trx, (lock_t *)lock);
+				/* Below function will roll back either trx
+				or lock->trx depending on priority of the
+				transaction. */
+				wsrep_kill_victim(const_cast<trx_t*>(trx), lock);
 				trx_mutex_exit(lock->trx);
 			}
 #endif /* WITH_WSREP */
@@ -1947,19 +1955,21 @@ Create a new lock.
 @param[in] owns_trx_mutex	true if caller owns the trx_t::mutex
 @param[in] add_to_hash		add the lock to hash table
 @param[in] prdt			Predicate lock (optional)
+@param[in,out] c_lock		Conflicting lock request or NULL
+				in Galera conflicting lock is selected
+				as deadlock victim if requester
+				is BF transaction.
 @return a new lock instance */
 lock_t*
-RecLock::create(trx_t* trx, bool owns_trx_mutex, bool add_to_hash, const lock_prdt_t* prdt)
-{
-	return create(NULL, trx, owns_trx_mutex, add_to_hash, prdt);
-}
-lock_t*
 RecLock::create(
-	lock_t* const c_lock,
 	trx_t*	trx,
 	bool	owns_trx_mutex,
 	bool	add_to_hash,
-	const	lock_prdt_t* prdt)
+	const	lock_prdt_t* prdt
+#ifdef WITH_WSREP
+	,lock_t* c_lock
+#endif /* WITH_WSREP */
+)
 {
 	ut_ad(lock_mutex_own());
 	ut_ad(owns_trx_mutex == trx_mutex_own(trx));
@@ -2045,7 +2055,7 @@ RecLock::create(
 			trx_mutex_exit(c_lock->trx);
 
 			if (wsrep_debug) {
-				ib::info() << "WSREP: c_lock canceled " << c_lock->trx->id;
+				ib::info() << "WSREP: c_lock canceled " << ib::hex(c_lock->trx->id);
 				ib::info() << " SQL1: "
 					   << wsrep_thd_query(c_lock->trx->mysql_thd);
 				ib::info() << " SQL2: "
@@ -2182,8 +2192,8 @@ RecLock::mark_trx_for_rollback(trx_t* trx)
 	if (thd != NULL) {
 
 		char	buffer[1024];
-		ib::info() << "Blocking transaction: ID: " << trx->id << " - "
-			<< " Blocked transaction ID: "<< m_trx->id << " - "
+		ib::info() << "Blocking transaction: ID: " << ib::hex(trx->id) << " - "
+			   << " Blocked transaction ID: "<< ib::hex(m_trx->id) << " - "
 			<< thd_get_error_context_description(thd, buffer, sizeof(buffer),
 						512);
 	}
@@ -2224,7 +2234,7 @@ queue is itself waiting roll it back, also do a deadlock check and resolve.
 	as a victim, and we got the lock immediately: no need to
 	wait then */
 dberr_t
-RecLock::add_to_waitq(const lock_t* wait_for, const lock_prdt_t* prdt)
+RecLock::add_to_waitq(lock_t* wait_for, const lock_prdt_t* prdt)
 {
 	ut_ad(lock_mutex_own());
 	ut_ad(m_trx == thr_get_trx(m_thr));
@@ -2259,7 +2269,12 @@ RecLock::add_to_waitq(const lock_t* wait_for, const lock_prdt_t* prdt)
 	bool	high_priority = trx_is_high_priority(m_trx);
 
 	/* Don't queue the lock to hash table, if high priority transaction. */
-	lock_t*	lock = create(m_trx, true, !high_priority, prdt);
+	lock_t*	lock = create(
+		m_trx, true, !high_priority, prdt
+#ifdef WITH_WSREP
+		,wait_for
+#endif /* WITH_WSREP */
+	);
 
 	/* Attempt to jump over the low priority waiting locks. */
 	if (high_priority && jump_queue(lock, wait_for)) {
@@ -2268,10 +2283,18 @@ RecLock::add_to_waitq(const lock_t* wait_for, const lock_prdt_t* prdt)
 		return(DB_SUCCESS);
 	}
 
+#ifdef WITH_WSREP
+	if (!lock_get_wait(lock) && wsrep_thd_is_BF(m_trx->mysql_thd, FALSE)) {
+		if (wsrep_debug) {
+			ib::info() << "WSREP: BF thread got lock granted early, ID " << ib::hex(lock->trx->id)
+				   << " query: " << wsrep_thd_query(m_trx->mysql_thd);
+		}
+		return(DB_SUCCESS);
+        }
+#endif /* WITH_WSREP */
 	ut_ad(lock_get_wait(lock));
 
-	dberr_t	err = deadlock_check(lock);
-
+	dberr_t err = deadlock_check(lock);
 	ut_ad(trx_mutex_own(m_trx));
 
 	// Move it only when it does not cause a deadlock.
@@ -2553,8 +2576,7 @@ lock_rec_lock_slow(
 		err = DB_SUCCESS;
 
 	} else {
-
-		const lock_t* wait_for = lock_rec_other_has_conflicting(
+		lock_t* wait_for = lock_rec_other_has_conflicting(
 			mode, block, heap_no, trx);
 
 		if (wait_for != NULL) {
@@ -2684,6 +2706,14 @@ lock_rec_has_to_wait_in_queue(
 #ifdef WITH_WSREP
 			if (wsrep_thd_is_BF(wait_lock->trx->mysql_thd, FALSE) &&
 			    wsrep_thd_is_BF(lock->trx->mysql_thd, TRUE)) {
+				if (wsrep_debug) {
+					ib::info() << "WSREP: waiting BF trx: " << ib::hex(wait_lock->trx->id)
+						   << " query: " << wsrep_thd_query(wait_lock->trx->mysql_thd);
+					lock_rec_print(stderr, wait_lock);
+					ib::info() << "WSREP: do not wait another BF trx: " << ib::hex(lock->trx->id)
+						   << " query: " << wsrep_thd_query(lock->trx->mysql_thd);
+					lock_rec_print(stderr, lock);
+				}
 				/* don't wait for another BF lock */
 				continue;
 			}
@@ -2786,8 +2816,8 @@ RecLock::jump_queue(
 
 		DBUG_LOG("trx",
 			 "Granting High Priority Transaction "
-			 << lock->trx->id << " a lock jumping over"
-			 << " waiting Transaction " << conflict_lock->trx->id);
+			<< ib::hex(lock->trx->id) << " a lock jumping over"
+			<< " waiting Transaction " << ib::hex(conflict_lock->trx->id));
 
 		lock_reset_lock_and_trx_wait(lock);
 		return(true);
@@ -2958,9 +2988,9 @@ RecLock::make_trx_hit_list(
 			ut_ad(trx->lock.wait_lock != next);
 
 			DBUG_LOG("trx", "High Priority Transaction "
-				 << lock->trx->id
+				<< ib::hex(lock->trx->id)
 				 << " waking up blocking transaction "
-				 << trx->id);
+				<< ib::hex(trx->id));
 
 			trx->lock.was_chosen_as_deadlock_victim = true;
 			lock_cancel_waiting_and_release(trx->lock.wait_lock);
@@ -3050,22 +3080,21 @@ lock_grant_and_move_on_page(
 			&& lock_get_wait(lock)
 			&& !lock_rec_has_to_wait_in_queue(lock)) {
 
-			
 			bool exit_trx_mutex = false;
-			
+
 			if (lock->trx->abort_type != TRX_SERVER_ABORT) {
 				ut_ad(trx_mutex_own(lock->trx));
 				trx_mutex_exit(lock->trx);
 				exit_trx_mutex = true;
 			}
-			
+
 			lock_grant(lock, false);
-			
+
 			if (exit_trx_mutex) {
 				ut_ad(!trx_mutex_own(lock->trx));
 				trx_mutex_enter(lock->trx);
 			}
-			
+
 			if (previous != NULL) {
 				/* Move the lock to the head of the list. */
 				HASH_GET_NEXT(hash, previous) = HASH_GET_NEXT(hash, lock);
@@ -3161,9 +3190,9 @@ lock_rec_dequeue_from_page(
 				}
 			}
 		}
-		} else {
-			lock_grant_and_move_on_page(lock_hash, space, page_no);
-		}
+	} else {
+		lock_grant_and_move_on_page(lock_hash, space, page_no);
+	}
 }
 
 /*************************************************************//**
@@ -4389,7 +4418,7 @@ lock_table_create(
 		ut_list_insert(table->locks, c_lock, lock, TableLockGetNode());
 		if (wsrep_debug) {
 			ib::info() << "table lock BF conflict for " <<
-				c_lock->trx->id;
+				ib::hex(c_lock->trx->id);
 			ib::info() << " SQL: "
 				   << wsrep_thd_query(c_lock->trx->mysql_thd);
 		}
@@ -4425,7 +4454,7 @@ lock_table_create(
 		}
 
 		if (wsrep_debug) {
-			ib::info() << "WSREP: c_lock canceled " << c_lock->trx->id;
+			ib::info() << "WSREP: c_lock canceled " << ib::hex(c_lock->trx->id);
 			ib::info() << " SQL: "
 					   << wsrep_thd_query(c_lock->trx->mysql_thd);
 		}
@@ -4697,7 +4726,7 @@ Checks if other transactions have an incompatible mode lock request in
 the lock queue.
 @return lock or NULL */
 UNIV_INLINE
-const lock_t*
+lock_t*
 lock_table_other_has_incompatible(
 /*==============================*/
 	const trx_t*		trx,	/*!< in: transaction, or NULL if all
@@ -4708,7 +4737,7 @@ lock_table_other_has_incompatible(
 	const dict_table_t*	table,	/*!< in: table */
 	lock_mode		mode)	/*!< in: lock mode */
 {
-	const lock_t*	lock;
+	lock_t*	lock;
 
 	ut_ad(lock_mutex_own());
 
@@ -4757,7 +4786,7 @@ lock_table(
 {
 	trx_t*		trx;
 	dberr_t		err;
-	const lock_t*	wait_for;
+	lock_t*		wait_for;
 
 	ut_ad(table && thr);
 
@@ -4813,9 +4842,9 @@ lock_table(
 	mode: this trx may have to wait */
 
 	if (wait_for != NULL) {
-		err = lock_table_enqueue_waiting((lock_t*)wait_for, mode | flags, table, thr);
+		err = lock_table_enqueue_waiting(wait_for, mode | flags, table, thr);
 	} else {
-		lock_table_create(table, mode | flags, trx);
+		lock_table_create(wait_for, table, mode | flags, trx);
 
 		ut_a(!flags || mode == LOCK_S || mode == LOCK_X);
 
@@ -6744,7 +6773,7 @@ lock_rec_insert_check_and_lock(
 
 	const ulint	type_mode = LOCK_X | LOCK_GAP | LOCK_INSERT_INTENTION;
 
-	const lock_t*	wait_for = lock_rec_other_has_conflicting(
+	lock_t*	wait_for = lock_rec_other_has_conflicting(
 				type_mode, block, heap_no, trx);
 
 	if (wait_for != NULL) {
@@ -8486,16 +8515,7 @@ DeadlockChecker::check_and_resolve(const lock_t* lock, trx_t* trx)
 			ut_ad(trx == checker.m_start);
 			ut_ad(trx == victim_trx);
 
-#ifdef WITH_WSREP
-			if (!wsrep_thd_is_BF(victim_trx->mysql_thd, TRUE))
-			{
-#endif /* WITH_WSREP */
-				rollback_print(victim_trx, lock);
-#ifdef WITH_WSREP
-			} else {
-			  /* BF processor */;
-			}
-#endif /* WITH_WSREP */
+			rollback_print(victim_trx, lock);
 
 			MONITOR_INC(MONITOR_DEADLOCK);
 
diff --git a/storage/innobase/lock/lock0prdt.cc b/storage/innobase/lock/lock0prdt.cc
index 88573b8a71a..dc2c6e2d15e 100644
--- a/storage/innobase/lock/lock0prdt.cc
+++ b/storage/innobase/lock/lock0prdt.cc
@@ -290,7 +290,7 @@ Checks if some other transaction has a conflicting predicate
 lock request in the queue, so that we have to wait.
 @return	lock or NULL */
 static
-const lock_t*
+lock_t*
 lock_prdt_other_has_conflicting(
 /*============================*/
 	ulint			mode,	/*!< in: LOCK_S or LOCK_X,
@@ -305,10 +305,10 @@ lock_prdt_other_has_conflicting(
 {
 	ut_ad(lock_mutex_own());
 
-	for (const lock_t* lock = lock_rec_get_first(
+	for (lock_t* lock = lock_rec_get_first(
 		lock_hash_get(mode), block, PRDT_HEAPNO);
 	     lock != NULL;
-	     lock = lock_rec_get_next_const(PRDT_HEAPNO, lock)) {
+	     lock = lock_rec_get_next(PRDT_HEAPNO, lock)) {
 
 		if (lock->trx == trx) {
 			continue;
@@ -565,7 +565,7 @@ lock_prdt_insert_check_and_lock(
 
 	const ulint	mode = LOCK_X | LOCK_PREDICATE | LOCK_INSERT_INTENTION;
 
-	const lock_t*	wait_for = lock_prdt_other_has_conflicting(
+	lock_t*	wait_for = lock_prdt_other_has_conflicting(
 		mode, block, prdt, trx);
 
 	if (wait_for != NULL) {
@@ -854,7 +854,7 @@ lock_prdt_lock(
 
 			if (lock == NULL) {
 
-				const lock_t*	wait_for;
+				lock_t*	wait_for;
 
 				wait_for = lock_prdt_other_has_conflicting(
 					prdt_mode, block, prdt, trx);
diff --git a/storage/innobase/lock/lock0wait.cc b/storage/innobase/lock/lock0wait.cc
index 0ed55558dc4..c41821412af 100644
--- a/storage/innobase/lock/lock0wait.cc
+++ b/storage/innobase/lock/lock0wait.cc
@@ -183,20 +183,38 @@ lock_wait_table_reserve_slot(
 /*********************************************************************//**
 check if lock timeout was for priority thread,
 as a side effect trigger lock monitor
+@param[in]    trx    transaction owning the lock
+@param[in]    locked true if trx and lock_sys_mutex is ownd
 @return	false for regular lock timeout */
-static ibool
+static
+bool
 wsrep_is_BF_lock_timeout(
-/*====================*/
-    trx_t* trx) /* in: trx to check for lock priority */
+	const trx_t*	trx,
+	bool		locked = true)
 {
-	if (wsrep_on_trx(trx) && wsrep_thd_is_BF(trx->mysql_thd, FALSE)) {
-		fprintf(stderr, "WSREP: BF lock wait long\n");
+	if (wsrep_on_trx(trx)
+	    && wsrep_thd_is_BF(trx->mysql_thd, FALSE)
+	    && trx->error_state != DB_DEADLOCK) {
+		ib::info() << "WSREP: BF lock wait long for trx:" << ib::hex(trx->id)
+			   << " query: " << wsrep_thd_query(trx->mysql_thd);
+		if (!locked) {
+			lock_mutex_enter();
+		}
+
+		ut_ad(lock_mutex_own());
+
+		wsrep_trx_print_locking(stderr, trx, 3000);
+
+		if (!locked) {
+			lock_mutex_exit();
+		}
+
 		srv_print_innodb_monitor 	= TRUE;
 		srv_print_innodb_lock_monitor 	= TRUE;
 		os_event_set(srv_monitor_event);
-		return TRUE;
+		return true;
 	}
-	return FALSE;
+	return false;
 }
 #endif /* WITH_WSREP */
 
@@ -399,7 +417,7 @@ lock_wait_suspend_thread(
 	    && wait_time > (double) lock_wait_timeout
 #ifdef WITH_WSREP
 	    && (!wsrep_on_trx(trx) ||
-	       (!wsrep_is_BF_lock_timeout(trx) && trx->error_state != DB_DEADLOCK))
+	       (!wsrep_is_BF_lock_timeout(trx, false) && trx->error_state != DB_DEADLOCK))
 #endif /* WITH_WSREP */
 	    && !trx_is_high_priority(trx)) {