MDEV-18706 InnoDB locking code debug helpers

storage/innobase/handler/ha_innodb.cc

@@ -19689,6 +19689,7 @@ wsrep_innobase_kill_one_trx(
 
 			if (wait_lock) {
 				WSREP_DEBUG("canceling wait lock");
+				DBUG_LOG("ib_lock", VICTIM(victim_trx) << *wait_lock);
 				victim_trx->lock.was_chosen_as_deadlock_victim= TRUE;
 				lock_cancel_waiting_and_release(wait_lock);
 			}

storage/innobase/include/lock0lock.h

@@ -1050,4 +1050,28 @@ lock_get_info(
 
 #include "lock0lock.ic"
 
+/** The global output operator is overloaded to conveniently
+print the lock_table_t object into the given output stream.
+@param[in,out]	out	the output stream
+@param[in]	lock	the table lock
+@return the given output stream */
+inline
+std::ostream&
+operator<<(std::ostream& out, const lock_table_t& lock)
+{
+	return(lock.print(out));
+}
+
+/** The global output operator is overloaded to conveniently
+print the ib_lock_t object into the given output stream.
+@param[in,out]	out	the output stream
+@param[in]	lock	the record lock
+@return the given output stream */
+inline
+std::ostream&
+operator<<(std::ostream& out, const ib_lock_t& lock)
+{
+	return(lock.print(out));
+}
+
 #endif

storage/innobase/include/lock0priv.h

@@ -48,56 +48,21 @@ those functions in lock/ */
 inline
 std::ostream& lock_table_t::print(std::ostream& out) const
 {
-	out << "[lock_table_t: name=" << table->name << "]";
+	out << "[" << table->name.m_name << "]";
 	return(out);
 }
 
-/** The global output operator is overloaded to conveniently
-print the lock_table_t object into the given output stream.
-@param[in,out]	out	the output stream
-@param[in]	lock	the table lock
-@return the given output stream */
-inline
-std::ostream&
-operator<<(std::ostream& out, const lock_table_t& lock)
-{
-	return(lock.print(out));
-}
-
-/** Convert the member 'type_mode' into a human readable string.
-@return human readable string */
-inline
-std::string
-ib_lock_t::type_mode_string() const
-{
-	std::ostringstream sout;
-	sout << type_string();
-	sout << " | " << lock_mode_string(mode());
-
-	if (is_record_not_gap()) {
-		sout << " | LOCK_REC_NOT_GAP";
-	}
-
-	if (is_waiting()) {
-		sout << " | LOCK_WAIT";
-	}
-
-	if (is_gap()) {
-		sout << " | LOCK_GAP";
-	}
-
-	if (is_insert_intention()) {
-		sout << " | LOCK_INSERT_INTENTION";
-	}
-	return(sout.str());
-}
-
 inline
 std::ostream&
 ib_lock_t::print(std::ostream& out) const
 {
-	out << "[lock_t: type_mode=" << type_mode << "("
-		<< type_mode_string() << ")";
+	out << "[trx=" << trx << "(" << trx->lock.trx_locks.count
+		<< ":" << trx->lock.table_locks.size() << "), ";
+	if (index) {
+		out << "index=" << index << "("
+			<< (index->is_primary() ? "#" : index->name()) << "), ";
+	}
+	out << "type_mode=" << type_mode << "=" << type_mode_string() << " ";
 
 	if (is_record_lock()) {
 		out << un_member.rec_lock;
@@ -109,17 +74,6 @@ ib_lock_t::print(std::ostream& out) const
 	return(out);
 }
 
-inline
-std::ostream&
-operator<<(std::ostream& out, const ib_lock_t& lock)
-{
-	return(lock.print(out));
-}
-
-#ifdef UNIV_DEBUG
-extern ibool	lock_print_waits;
-#endif /* UNIV_DEBUG */
-
 /** Restricts the length of search we will do in the waits-for
 graph of transactions */
 static const ulint	LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK = 1000000;
@@ -594,6 +548,15 @@ lock_rec_get_first(
 	const buf_block_t*	block,	/*!< in: block containing the record */
 	ulint			heap_no);/*!< in: heap number of the record */
 
+/*********************************************************************//**
+Gets the mode from type_mode.
+@return mode */
+UNIV_INLINE
+enum lock_mode
+lock_get_mode(
+/*==========*/
+	const ib_uint32_t type_mode);
+
 /*********************************************************************//**
 Gets the mode of a lock.
 @return mode */
@@ -671,6 +634,7 @@ inline void lock_set_lock_and_trx_wait(lock_t* lock, trx_t* trx)
 
 	trx->lock.wait_lock = lock;
 	lock->type_mode |= LOCK_WAIT;
+	DBUG_LOG("ib_lock", "+WAIT("<< lock << ") " << *lock);
 }
 
 /** Reset the wait status of a lock.
@@ -683,6 +647,7 @@ inline void lock_reset_lock_and_trx_wait(lock_t* lock)
 	      || lock->trx->lock.wait_lock == lock);
 	lock->trx->lock.wait_lock = NULL;
 	lock->type_mode &= ~LOCK_WAIT;
+	DBUG_LOG("ib_lock", "-WAIT("<< lock << ") " << *lock);
 }
 
 inline

storage/innobase/include/lock0priv.ic

@@ -286,6 +286,18 @@ lock_rec_get_next_on_page_const(
 	return(NULL);
 }
 
+/*********************************************************************//**
+Gets the mode from type_mode.
+@return mode */
+UNIV_INLINE
+enum lock_mode
+lock_get_mode(
+/*==========*/
+	const ib_uint32_t type_mode)
+{
+	return(static_cast<enum lock_mode>(type_mode & LOCK_MODE_MASK));
+}
+
 /*********************************************************************//**
 Gets the mode of a lock.
 @return mode */
@@ -297,7 +309,7 @@ lock_get_mode(
 {
 	ut_ad(lock);
 
-	return(static_cast<enum lock_mode>(lock->type_mode & LOCK_MODE_MASK));
+	return(lock_get_mode(lock->type_mode));
 }
 
 /*********************************************************************//**

storage/innobase/include/lock0types.h

@@ -57,19 +57,19 @@ const char* lock_mode_string(enum lock_mode mode)
 {
 	switch (mode) {
 	case LOCK_IS:
-		return("LOCK_IS");
+		return("IS");
 	case LOCK_IX:
-		return("LOCK_IX");
+		return("IX");
 	case LOCK_S:
-		return("LOCK_S");
+		return("S");
 	case LOCK_X:
-		return("LOCK_X");
+		return("X");
 	case LOCK_AUTO_INC:
-		return("LOCK_AUTO_INC");
+		return("AUTO_INC");
 	case LOCK_NONE:
-		return("LOCK_NONE");
+		return("NONE");
 	case LOCK_NONE_UNSET:
-		return("LOCK_NONE_UNSET");
+		return("NONE_UNSET");
 	default:
 		ut_error;
 	}
@@ -109,7 +109,7 @@ struct lock_rec_t {
 inline
 std::ostream& lock_rec_t::print(std::ostream& out) const
 {
-	out << "[lock_rec_t: space=" << space << ", page_no=" << page_no
+	out << "[space=" << space << ", page_no=" << page_no
 		<< ", n_bits=" << n_bits << "]";
 	return(out);
 }
@@ -176,6 +176,51 @@ operator<<(std::ostream& out, const lock_rec_t& lock)
 #endif
 /* @} */
 
+inline
+const char*
+type_string(ulint type_mode)
+{
+	switch (type_mode & LOCK_TYPE_MASK) {
+	case LOCK_REC:
+		return("REC");
+	case LOCK_TABLE:
+		return("TABLE");
+	default:
+		ut_error;
+	}
+}
+
+/** Convert 'type_mode' into a human readable string.
+@return human readable string */
+inline
+std::string
+type_mode_string(ulint type_mode)
+{
+	std::ostringstream sout;
+	lock_mode mode = static_cast<enum lock_mode>(type_mode & LOCK_MODE_MASK);
+	if (type_mode & LOCK_TYPE_MASK) {
+		sout << type_string(type_mode) << "|";
+	}
+	sout << lock_mode_string(mode);
+
+	if (type_mode & LOCK_REC_NOT_GAP) {
+		sout << "|REC_NOT_GAP";
+	}
+
+	if (type_mode & LOCK_WAIT) {
+		sout << "|WAIT";
+	}
+
+	if (type_mode & LOCK_GAP) {
+		sout << "|GAP";
+	}
+
+	if (type_mode & LOCK_INSERT_INTENTION) {
+		sout << "|INSERT_INTENTION";
+	}
+	return(sout.str());
+}
+
 /** Lock struct; protected by lock_sys->mutex */
 struct ib_lock_t
 {
@@ -254,23 +299,98 @@ struct ib_lock_t
 	@return the given output stream. */
 	std::ostream& print(std::ostream& out) const;
 
-	/** Convert the member 'type_mode' into a human readable string.
-	@return human readable string */
-	std::string type_mode_string() const;
+	std::string type_mode_string() const
+	{
+		return ::type_mode_string(type_mode);
+	}
 
 	const char* type_string() const
 	{
-		switch (type_mode & LOCK_TYPE_MASK) {
-		case LOCK_REC:
-			return("LOCK_REC");
-		case LOCK_TABLE:
-			return("LOCK_TABLE");
-		default:
-			ut_error;
-		}
+		return ::type_string(type_mode);
 	}
 };
 
 typedef UT_LIST_BASE_NODE_T(ib_lock_t) trx_lock_list_t;
 
+#ifndef DBUG_OFF
+/* Classes used to catch various locking situations in code */
+
+struct ADD /* add lock */
+{
+	const lock_t *lock;
+	ADD(const lock_t *l) : lock(l)
+	{
+	}
+};
+
+inline
+std::ostream&
+operator<<(std::ostream& out, const ADD& a)
+{
+	out << "ADD(" << a.lock << ") ";
+	return out;
+}
+
+struct VICTIM /* deadlock victim */
+{
+	const trx_t *trx;
+	bool set;
+	VICTIM(const trx_t *t, bool s = true) : trx(t), set(s)
+	{
+	}
+};
+
+inline
+std::ostream&
+operator<<(std::ostream& out, const VICTIM& v)
+{
+	out << (v.set ? '+' : '-') << "VICTIM(trx=" << v.trx << ") ";
+	return out;
+}
+
+struct WEAKER /* precise_mode is weaker than existing lock (of same trx) */
+{
+	ulint precise_mode;
+	lock_t *lock;
+	WEAKER(ulint m, lock_t *l) : precise_mode(m), lock(l)
+	{
+	}
+};
+
+inline
+std::ostream&
+operator<<(std::ostream& out, const WEAKER& w)
+{
+	out << "WEAKER(" << type_mode_string(w.precise_mode) << ", " << w.lock << ") ";
+	w.lock->print(out);
+	out << " ";
+	return out;
+}
+
+struct CONFLICTS /* precise_mode conflicts (or doesn't) with any existing locks */
+{
+	const trx_t *trx;
+	ulint precise_mode;
+	const lock_t *conflict;
+	CONFLICTS(const trx_t *t, ulint m, const lock_t *c) :
+		trx(t), precise_mode(m), conflict(c)
+	{
+	}
+};
+
+inline
+std::ostream&
+operator<<(std::ostream& out, const CONFLICTS& c)
+{
+	out << (c.conflict ? "CONFLICTS(trx=" : "NO_CONFLICTS(trx=")
+		<< c.trx << ", " << type_mode_string(c.precise_mode) << ", "
+		<< c.conflict  << ") ";
+	if (c.conflict) {
+		c.conflict->print(out);
+		out << " ";
+	}
+	return out;
+}
+
+#endif /* !DBUG_OFF */
 #endif /* lock0types_h */

storage/innobase/lock/lock0lock.cc

@@ -1013,6 +1013,7 @@ lock_rec_has_expl(
 {
 	lock_t*	lock;
 
+	DBUG_ENTER("lock_rec_has_expl");
 	ut_ad(lock_mutex_own());
 	ut_ad((precise_mode & LOCK_MODE_MASK) == LOCK_S
 	      || (precise_mode & LOCK_MODE_MASK) == LOCK_X);
@@ -1024,11 +1025,12 @@ lock_rec_has_expl(
 
 		if (lock->is_stronger(precise_mode, heap_no, trx)) {
 
-			return(lock);
+			DBUG_LOG("ib_lock", WEAKER(precise_mode, lock));
+			DBUG_RETURN(lock);
 		}
 	}
 
-	return(NULL);
+	DBUG_RETURN(NULL);
 }
 
 #ifdef UNIV_DEBUG
@@ -1162,6 +1164,7 @@ lock_rec_other_has_conflicting(
 {
 	lock_t*		res = NULL;
 
+	DBUG_ENTER("lock_rec_other_has_conflicting");
 	ut_ad(lock_mutex_own());
 
 	bool	is_supremum = (heap_no == PAGE_HEAP_NO_SUPREMUM);
@@ -1174,7 +1177,9 @@ lock_rec_other_has_conflicting(
 		same types then we don't have to wait for any locks. */
 		if (lock->is_stronger(mode, heap_no, trx)) {
 
-			return(NULL);
+			DBUG_LOG("ib_lock", CONFLICTS(trx, mode, NULL)
+				 << "because: " << WEAKER(mode, lock)) ;
+			DBUG_RETURN(NULL);
 		}
 
 		if (!res && lock_rec_has_to_wait(true, trx, mode, lock, is_supremum)) {
@@ -1193,7 +1198,8 @@ lock_rec_other_has_conflicting(
 	}
 #endif /* WITH_WSREP */
 
-	return(res);
+	DBUG_LOG("ib_lock", CONFLICTS(trx, mode, res));
+	DBUG_RETURN(res);
 }
 
 /*********************************************************************//**
@@ -1469,6 +1475,7 @@ lock_rec_create_low(
 		lock->un_member.rec_lock.n_bits = 8;
  	}
 	lock_rec_bitmap_reset(lock);
+	DBUG_LOG("ib_lock", ADD(lock) << *lock);
 	lock_rec_set_nth_bit(lock, heap_no);
 	index->table->n_rec_locks++;
 	ut_ad(index->table->get_ref_count() > 0 || !index->table->can_be_evicted);
@@ -1497,7 +1504,7 @@ lock_rec_create_low(
 		 */
 		trx_mutex_enter(c_lock->trx);
 		if (c_lock->trx->lock.que_state == TRX_QUE_LOCK_WAIT) {
-
+			DBUG_LOG("ib_lock", VICTIM(c_lock->trx) << *c_lock);
 			c_lock->trx->lock.was_chosen_as_deadlock_victim = TRUE;
 
 			if (UNIV_UNLIKELY(wsrep_debug)) {
@@ -3671,6 +3678,7 @@ lock_table_create(
 		trx_mutex_enter(c_lock->trx);
 
 		if (c_lock->trx->lock.que_state == TRX_QUE_LOCK_WAIT) {
+			DBUG_LOG("ib_lock", VICTIM(c_lock->trx) << *c_lock);
 			c_lock->trx->lock.was_chosen_as_deadlock_victim = TRUE;
 
 			if (UNIV_UNLIKELY(wsrep_debug)) {
@@ -3703,6 +3711,7 @@ lock_table_create(
 		lock_set_lock_and_trx_wait(lock, trx);
 	}
 
+	DBUG_LOG("ib_lock", ADD(lock) << *lock);
 	lock->trx->lock.table_locks.push_back(lock);
 
 	MONITOR_INC(MONITOR_TABLELOCK_CREATED);
@@ -3838,6 +3847,8 @@ lock_table_remove_low(
 	UT_LIST_REMOVE(trx->lock.trx_locks, lock);
 	ut_list_remove(table->locks, lock, TableLockGetNode());
 
+	DBUG_LOG("ib_lock", "DEL("<< lock << ") " << *lock);
+
 	MONITOR_INC(MONITOR_TABLELOCK_REMOVED);
 	MONITOR_DEC(MONITOR_NUM_TABLELOCK);
 }
@@ -3883,7 +3894,8 @@ lock_table_enqueue_waiting(
 	}
 
 #ifdef WITH_WSREP
-	if (trx->is_wsrep() && trx->lock.was_chosen_as_deadlock_victim) {
+	if (trx->lock.was_chosen_as_deadlock_victim && trx->is_wsrep()) {
+		DBUG_LOG("ib_lock", "DEADLOCK(" << trx << ") ");
 		return(DB_DEADLOCK);
 	}
 #endif /* WITH_WSREP */
@@ -3906,6 +3918,7 @@ lock_table_enqueue_waiting(
 		lock_table_remove_low(lock);
 		lock_reset_lock_and_trx_wait(lock);
 
+		DBUG_LOG("ib_lock", "DEADLOCK(" << trx << ") ");
 		return(DB_DEADLOCK);
 
 	} else if (trx->lock.wait_lock == NULL) {
@@ -3918,6 +3931,7 @@ lock_table_enqueue_waiting(
 	trx->lock.que_state = TRX_QUE_LOCK_WAIT;
 
 	trx->lock.wait_started = time(NULL);
+	DBUG_LOG("ib_lock", VICTIM(trx, false));
 	trx->lock.was_chosen_as_deadlock_victim = false;
 
 	ut_a(que_thr_stop(thr));
@@ -5780,6 +5794,7 @@ lock_rec_convert_impl_to_expl_for_trx(
 	if (!trx_state_eq(trx, TRX_STATE_COMMITTED_IN_MEMORY)
 	    && !lock_rec_has_expl(LOCK_X | LOCK_REC_NOT_GAP,
 				  block, heap_no, trx)) {
+		DBUG_LOG("ib_lock", "IMPL_TO_EXPL(trx=" << trx << ")");
 		lock_rec_add_to_queue(LOCK_REC | LOCK_X | LOCK_REC_NOT_GAP,
 				      block, heap_no, index, trx, true);
 	}
@@ -7200,6 +7215,7 @@ DeadlockChecker::trx_rollback()
 
 	trx_mutex_enter(trx);
 
+	DBUG_LOG("ib_lock", VICTIM(trx));
 	trx->lock.was_chosen_as_deadlock_victim = true;
 
 	lock_cancel_waiting_and_release(trx->lock.wait_lock);

storage/innobase/lock/lock0wait.cc

@@ -262,6 +262,7 @@ lock_wait_suspend_thread(
 		if (trx->lock.was_chosen_as_deadlock_victim) {
 
 			trx->error_state = DB_DEADLOCK;
+			DBUG_LOG("ib_lock", "DEADLOCK(" << trx << ") ");
 			trx->lock.was_chosen_as_deadlock_victim = false;
 		}
 
@@ -441,6 +442,7 @@ lock_wait_release_thread_if_suspended(
 		if (trx->lock.was_chosen_as_deadlock_victim) {
 
 			trx->error_state = DB_DEADLOCK;
+			DBUG_LOG("ib_lock", "DEADLOCK(" << trx << ") ");
 			trx->lock.was_chosen_as_deadlock_victim = false;
 		}
 

storage/innobase/ut/ut0ut.cc

@@ -673,4 +673,39 @@ fatal_or_error::~fatal_or_error()
 
 } // namespace ib
 
+#ifndef DBUG_OFF
+static std::string dbug_str;
+
+template <class T>
+const char * dbug_print(T &obj)
+{
+	std::ostringstream os;
+	os.str("");
+	os.clear();
+	obj.print(os);
+	dbug_str = os.str();
+	return dbug_str.c_str();
+}
+
+const char * dbug_print(ib_lock_t *obj)
+{
+	return dbug_print(*obj);
+}
+
+const char * dbug_print(lock_rec_t *obj)
+{
+	return dbug_print(*obj);
+}
+
+const char * dbug_print(lock_table_t *obj)
+{
+	return dbug_print(*obj);
+}
+
+const char * dbug_print_lock_mode(ib_uint32_t type_mode)
+{
+	dbug_str = type_mode_string(type_mode);
+	return dbug_str.c_str();
+}
+#endif /* !DBUG_OFF */
 #endif /* !UNIV_INNOCHECKSUM */