- Place back STR string declarations for lock/unlock strings used for KTR_LOCK

  tracing in order to avoid duplication.
- Insert some tracepoints back into the mutex acq/rel code, thus ensuring
  that we can trace all lock acq/rel's again.
- All CURPROC != NULL checks are MPASS()es (under MUTEX_DEBUG) because they
  signify a serious mutex corruption.
- Change up some KASSERT()s to MPASS()es, and vice-versa, depending on the
  type of problem we're debugging (INVARIANTS is used here to check that
  the API is being used properly whereas MUTEX_DEBUG is used to ensure that
  something general isn't happening that will have bad impact on mutex
  locks).

Reminded by: jhb, jake, asmodai

4 files changed, 92 insertions, 45 deletions

diff --git a/sys/kern/kern_mutex.c b/sys/kern/kern_mutex.c
index b7d0b36..7131b31 100644
--- a/sys/kern/kern_mutex.c
+++ b/sys/kern/kern_mutex.c
@@ -163,6 +163,14 @@ static int	mtx_cur_cnt;
 static int	mtx_max_cnt;
 
 /*
+ * Couple of strings for KTR_LOCK tracing in order to avoid duplicates.
+ */
+char	STR_mtx_lock_slp[] = "GOT (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_slp[] = "REL (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_lock_spn[] = "GOT (spin) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_spn[] = "REL (spin) %s [%p] r=%d at %s:%d";
+
+/*
  * Prototypes for non-exported routines.
  *
  * NOTE: Prototypes for witness routines are placed at the bottom of the file. 
@@ -302,12 +310,13 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 {
 	int rval;
 
-	KASSERT(CURPROC != NULL, ("curproc is NULL in _mtx_trylock"));
+	MPASS(CURPROC != NULL);
 
 	/*
 	 * _mtx_trylock does not accept MTX_NOSWITCH option.
 	 */
-	MPASS((opts & MTX_NOSWITCH) == 0);
+	KASSERT((opts & MTX_NOSWITCH) == 0,
+	    ("mtx_trylock() called with invalid option flag(s) %d", opts));
 
 	rval = _obtain_lock(m, CURTHD);
 
@@ -317,7 +326,8 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 		 * We do not handle recursion in _mtx_trylock; see the
 		 * note at the top of the routine.
 		 */
-		MPASS(!mtx_recursed(m));
+		KASSERT(!mtx_recursed(m),
+		    ("mtx_trylock() called on a recursed mutex"));
 		witness_try_enter(m, (opts | m->mtx_flags), file, line);
 	}
 #endif	/* WITNESS */
@@ -344,13 +354,13 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		m->mtx_recurse++;
 		atomic_set_ptr(&m->mtx_lock, MTX_RECURSED);
 		if ((opts & MTX_QUIET) == 0)
-			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recurse", m);
+			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recursing", m);
 		return;
 	}
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR3(KTR_LOCK, "mtx_lock: %p contested (lock=%p) [%p]", m,
-		    (void *)m->mtx_lock, (void *)RETIP(m));
+		CTR3(KTR_LOCK, "_mtx_lock_sleep: %p contested (lock=%p) [%p]",
+		    m, (void *)m->mtx_lock, (void *)RETIP(m));
 
 	/*
 	 * Save our priority. Even though p_nativepri is protected by
@@ -383,8 +393,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		 */
 		if (v == MTX_CONTESTED) {
 			p1 = TAILQ_FIRST(&m->mtx_blocked);
-			KASSERT(p1 != NULL,
-			    ("contested mutex has no contesters"));
+			MPASS(p1 != NULL);
 			m->mtx_lock = (uintptr_t)p | MTX_CONTESTED;
 
 			if (p1->p_priority < p->p_priority)
@@ -421,7 +430,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 			if (it->it_interrupted) {
 				if ((opts & MTX_QUIET) == 0)
 					CTR2(KTR_LOCK,
-					    "mtx_lock: 0x%x interrupted 0x%x",
+				    "_mtx_lock_sleep: 0x%x interrupted 0x%x",
 					    it, it->it_interrupted);
 				intr_thd_fixup(it);
 			}
@@ -486,7 +495,7 @@ _mtx_lock_spin(struct mtx *m, int opts, u_int mtx_intr, const char *file,
 	int i = 0;
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR1(KTR_LOCK, "mtx_lock_spin: %p spinning", m);
+		CTR1(KTR_LOCK, "_mtx_lock_spin: %p spinning", m);
 
 	for (;;) {
 		if (_obtain_lock(m, CURPROC))
@@ -530,10 +539,6 @@ _mtx_unlock_sleep(struct mtx *m, int opts, const char *file, int line)
 	p = CURPROC;
 	MPASS4(mtx_owned(m), "mtx_owned(mpp)", file, line);
 
-	if ((opts & MTX_QUIET) == 0)
-		CTR5(KTR_LOCK, "REL %s [%p] r=%d at %s:%d", m->mtx_description,
-		    m, m->mtx_recurse, file, line);
-
 	if (mtx_recursed(m)) {
 		if (--(m->mtx_recurse) == 0)
 			atomic_clear_ptr(&m->mtx_lock, MTX_RECURSED);
diff --git a/sys/kern/subr_turnstile.c b/sys/kern/subr_turnstile.c
index b7d0b36..7131b31 100644
--- a/sys/kern/subr_turnstile.c
+++ b/sys/kern/subr_turnstile.c
@@ -163,6 +163,14 @@ static int	mtx_cur_cnt;
 static int	mtx_max_cnt;
 
 /*
+ * Couple of strings for KTR_LOCK tracing in order to avoid duplicates.
+ */
+char	STR_mtx_lock_slp[] = "GOT (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_slp[] = "REL (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_lock_spn[] = "GOT (spin) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_spn[] = "REL (spin) %s [%p] r=%d at %s:%d";
+
+/*
  * Prototypes for non-exported routines.
  *
  * NOTE: Prototypes for witness routines are placed at the bottom of the file. 
@@ -302,12 +310,13 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 {
 	int rval;
 
-	KASSERT(CURPROC != NULL, ("curproc is NULL in _mtx_trylock"));
+	MPASS(CURPROC != NULL);
 
 	/*
 	 * _mtx_trylock does not accept MTX_NOSWITCH option.
 	 */
-	MPASS((opts & MTX_NOSWITCH) == 0);
+	KASSERT((opts & MTX_NOSWITCH) == 0,
+	    ("mtx_trylock() called with invalid option flag(s) %d", opts));
 
 	rval = _obtain_lock(m, CURTHD);
 
@@ -317,7 +326,8 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 		 * We do not handle recursion in _mtx_trylock; see the
 		 * note at the top of the routine.
 		 */
-		MPASS(!mtx_recursed(m));
+		KASSERT(!mtx_recursed(m),
+		    ("mtx_trylock() called on a recursed mutex"));
 		witness_try_enter(m, (opts | m->mtx_flags), file, line);
 	}
 #endif	/* WITNESS */
@@ -344,13 +354,13 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		m->mtx_recurse++;
 		atomic_set_ptr(&m->mtx_lock, MTX_RECURSED);
 		if ((opts & MTX_QUIET) == 0)
-			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recurse", m);
+			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recursing", m);
 		return;
 	}
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR3(KTR_LOCK, "mtx_lock: %p contested (lock=%p) [%p]", m,
-		    (void *)m->mtx_lock, (void *)RETIP(m));
+		CTR3(KTR_LOCK, "_mtx_lock_sleep: %p contested (lock=%p) [%p]",
+		    m, (void *)m->mtx_lock, (void *)RETIP(m));
 
 	/*
 	 * Save our priority. Even though p_nativepri is protected by
@@ -383,8 +393,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		 */
 		if (v == MTX_CONTESTED) {
 			p1 = TAILQ_FIRST(&m->mtx_blocked);
-			KASSERT(p1 != NULL,
-			    ("contested mutex has no contesters"));
+			MPASS(p1 != NULL);
 			m->mtx_lock = (uintptr_t)p | MTX_CONTESTED;
 
 			if (p1->p_priority < p->p_priority)
@@ -421,7 +430,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 			if (it->it_interrupted) {
 				if ((opts & MTX_QUIET) == 0)
 					CTR2(KTR_LOCK,
-					    "mtx_lock: 0x%x interrupted 0x%x",
+				    "_mtx_lock_sleep: 0x%x interrupted 0x%x",
 					    it, it->it_interrupted);
 				intr_thd_fixup(it);
 			}
@@ -486,7 +495,7 @@ _mtx_lock_spin(struct mtx *m, int opts, u_int mtx_intr, const char *file,
 	int i = 0;
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR1(KTR_LOCK, "mtx_lock_spin: %p spinning", m);
+		CTR1(KTR_LOCK, "_mtx_lock_spin: %p spinning", m);
 
 	for (;;) {
 		if (_obtain_lock(m, CURPROC))
@@ -530,10 +539,6 @@ _mtx_unlock_sleep(struct mtx *m, int opts, const char *file, int line)
 	p = CURPROC;
 	MPASS4(mtx_owned(m), "mtx_owned(mpp)", file, line);
 
-	if ((opts & MTX_QUIET) == 0)
-		CTR5(KTR_LOCK, "REL %s [%p] r=%d at %s:%d", m->mtx_description,
-		    m, m->mtx_recurse, file, line);
-
 	if (mtx_recursed(m)) {
 		if (--(m->mtx_recurse) == 0)
 			atomic_clear_ptr(&m->mtx_lock, MTX_RECURSED);
diff --git a/sys/kern/subr_witness.c b/sys/kern/subr_witness.c
index b7d0b36..7131b31 100644
--- a/sys/kern/subr_witness.c
+++ b/sys/kern/subr_witness.c
@@ -163,6 +163,14 @@ static int	mtx_cur_cnt;
 static int	mtx_max_cnt;
 
 /*
+ * Couple of strings for KTR_LOCK tracing in order to avoid duplicates.
+ */
+char	STR_mtx_lock_slp[] = "GOT (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_slp[] = "REL (sleep) %s [%p] r=%d at %s:%d";
+char	STR_mtx_lock_spn[] = "GOT (spin) %s [%p] r=%d at %s:%d";
+char	STR_mtx_unlock_spn[] = "REL (spin) %s [%p] r=%d at %s:%d";
+
+/*
  * Prototypes for non-exported routines.
  *
  * NOTE: Prototypes for witness routines are placed at the bottom of the file. 
@@ -302,12 +310,13 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 {
 	int rval;
 
-	KASSERT(CURPROC != NULL, ("curproc is NULL in _mtx_trylock"));
+	MPASS(CURPROC != NULL);
 
 	/*
 	 * _mtx_trylock does not accept MTX_NOSWITCH option.
 	 */
-	MPASS((opts & MTX_NOSWITCH) == 0);
+	KASSERT((opts & MTX_NOSWITCH) == 0,
+	    ("mtx_trylock() called with invalid option flag(s) %d", opts));
 
 	rval = _obtain_lock(m, CURTHD);
 
@@ -317,7 +326,8 @@ _mtx_trylock(struct mtx *m, int opts, const char *file, int line)
 		 * We do not handle recursion in _mtx_trylock; see the
 		 * note at the top of the routine.
 		 */
-		MPASS(!mtx_recursed(m));
+		KASSERT(!mtx_recursed(m),
+		    ("mtx_trylock() called on a recursed mutex"));
 		witness_try_enter(m, (opts | m->mtx_flags), file, line);
 	}
 #endif	/* WITNESS */
@@ -344,13 +354,13 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		m->mtx_recurse++;
 		atomic_set_ptr(&m->mtx_lock, MTX_RECURSED);
 		if ((opts & MTX_QUIET) == 0)
-			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recurse", m);
+			CTR1(KTR_LOCK, "_mtx_lock_sleep: %p recursing", m);
 		return;
 	}
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR3(KTR_LOCK, "mtx_lock: %p contested (lock=%p) [%p]", m,
-		    (void *)m->mtx_lock, (void *)RETIP(m));
+		CTR3(KTR_LOCK, "_mtx_lock_sleep: %p contested (lock=%p) [%p]",
+		    m, (void *)m->mtx_lock, (void *)RETIP(m));
 
 	/*
 	 * Save our priority. Even though p_nativepri is protected by
@@ -383,8 +393,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		 */
 		if (v == MTX_CONTESTED) {
 			p1 = TAILQ_FIRST(&m->mtx_blocked);
-			KASSERT(p1 != NULL,
-			    ("contested mutex has no contesters"));
+			MPASS(p1 != NULL);
 			m->mtx_lock = (uintptr_t)p | MTX_CONTESTED;
 
 			if (p1->p_priority < p->p_priority)
@@ -421,7 +430,7 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 			if (it->it_interrupted) {
 				if ((opts & MTX_QUIET) == 0)
 					CTR2(KTR_LOCK,
-					    "mtx_lock: 0x%x interrupted 0x%x",
+				    "_mtx_lock_sleep: 0x%x interrupted 0x%x",
 					    it, it->it_interrupted);
 				intr_thd_fixup(it);
 			}
@@ -486,7 +495,7 @@ _mtx_lock_spin(struct mtx *m, int opts, u_int mtx_intr, const char *file,
 	int i = 0;
 
 	if ((opts & MTX_QUIET) == 0)
-		CTR1(KTR_LOCK, "mtx_lock_spin: %p spinning", m);
+		CTR1(KTR_LOCK, "_mtx_lock_spin: %p spinning", m);
 
 	for (;;) {
 		if (_obtain_lock(m, CURPROC))
@@ -530,10 +539,6 @@ _mtx_unlock_sleep(struct mtx *m, int opts, const char *file, int line)
 	p = CURPROC;
 	MPASS4(mtx_owned(m), "mtx_owned(mpp)", file, line);
 
-	if ((opts & MTX_QUIET) == 0)
-		CTR5(KTR_LOCK, "REL %s [%p] r=%d at %s:%d", m->mtx_description,
-		    m, m->mtx_recurse, file, line);
-
 	if (mtx_recursed(m)) {
 		if (--(m->mtx_recurse) == 0)
 			atomic_clear_ptr(&m->mtx_lock, MTX_RECURSED);
diff --git a/sys/sys/mutex.h b/sys/sys/mutex.h
index a765ee8..0557512 100644
--- a/sys/sys/mutex.h
+++ b/sys/sys/mutex.h
@@ -108,6 +108,14 @@ struct mtx {
 #ifdef _KERNEL
 
 /*
+ * Strings for KTR_LOCK tracing.
+ */
+extern char	STR_mtx_lock_slp[];
+extern char	STR_mtx_lock_spn[];
+extern char	STR_mtx_unlock_slp[];
+extern char	STR_mtx_unlock_spn[]; 
+
+/*
  * Prototypes
  *
  * NOTE: Functions prepended with `_' (underscore) are exported to other parts
@@ -244,30 +252,44 @@ int	_mtx_trylock(struct mtx *m, int opts, const char *file, int line);
 #define mtx_lock(m) do {						\
 	MPASS(CURPROC != NULL);						\
 	_get_sleep_lock((m), CURTHD, 0);				\
+	CTR5(KTR_LOCK, STR_mtx_lock_slp, (m)->mtx_description, (m),	\
+	    (m)->mtx_recurse, __FILE__,	__LINE__);			\
 	WITNESS_ENTER((m), (m)->mtx_flags, __FILE__, __LINE__);		\
 } while (0)
 
 #define mtx_lock_spin(m) do {						\
 	MPASS(CURPROC != NULL);						\
 	_get_spin_lock((m), CURTHD, 0);					\
+	CTR5(KTR_LOCK, STR_mtx_lock_spn, (m)->mtx_description, (m),	\
+	    (m)->mtx_recurse, __FILE__,	__LINE__);			\
 	WITNESS_ENTER((m), (m)->mtx_flags, __FILE__, __LINE__);		\
 } while (0)
 
 #define mtx_unlock(m) do {						\
 	MPASS(CURPROC != NULL);						\
 	WITNESS_EXIT((m), (m)->mtx_flags, __FILE__, __LINE__);		\
+	mtx_assert((m), MA_OWNED);					\
 	_rel_sleep_lock((m), CURTHD, 0);				\
+	CTR5(KTR_LOCK, STR_mtx_unlock_slp, (m)->mtx_description, (m),	\
+	    (m)->mtx_recurse, __FILE__,	__LINE__);			\
 } while (0)
 
 #define mtx_unlock_spin(m) do {						\
 	MPASS(CURPROC != NULL);						\
 	WITNESS_EXIT((m), (m)->mtx_flags, __FILE__, __LINE__);		\
+	mtx_assert((m), MA_OWNED);					\
 	_rel_spin_lock((m));						\
+	CTR5(KTR_LOCK, STR_mtx_unlock_spn, (m)->mtx_description, (m),	\
+	    (m)->mtx_recurse, __FILE__,	__LINE__);			\
 } while (0)
 
 #define mtx_lock_flags(m, opts) do {					\
 	MPASS(CURPROC != NULL);						\
 	_get_sleep_lock((m), CURTHD, (opts));				\
+	if (((opts) & MTX_QUIET) == 0)					\
+		CTR5(KTR_LOCK, STR_mtx_lock_slp,			\
+		    (m)->mtx_description, (m), (m)->mtx_recurse, 	\
+		    __FILE__, __LINE__);				\
 	WITNESS_ENTER((m), ((m)->mtx_flags | (opts)), __FILE__,		\
 	    __LINE__);							\
 } while (0)
@@ -275,6 +297,10 @@ int	_mtx_trylock(struct mtx *m, int opts, const char *file, int line);
 #define mtx_lock_spin_flags(m, opts) do {				\
 	MPASS(CURPROC != NULL);						\
 	_get_spin_lock((m), CURTHD, (opts));				\
+	if (((opts) & MTX_QUIET) == 0)					\
+		CTR5(KTR_LOCK, STR_mtx_lock_spn,			\
+		    (m)->mtx_description, (m), (m)->mtx_recurse, 	\
+		    __FILE__, __LINE__);				\
 	WITNESS_ENTER((m), ((m)->mtx_flags | (opts)), __FILE__,		\
 	    __LINE__);							\
 } while (0)
@@ -283,7 +309,12 @@ int	_mtx_trylock(struct mtx *m, int opts, const char *file, int line);
 	MPASS(CURPROC != NULL);						\
 	WITNESS_EXIT((m), ((m)->mtx_flags | (opts)), __FILE__,		\
 	    __LINE__);							\
+	mtx_assert((m), MA_OWNED);					\
 	_rel_sleep_lock((m), CURTHD, (opts));				\
+	if (((opts) & MTX_QUIET) == 0)					\
+		CTR5(KTR_LOCK, STR_mtx_unlock_slp,			\
+		    (m)->mtx_description, (m), (m)->mtx_recurse, 	\
+		    __FILE__, __LINE__);				\
 } while (0)
 
 /*
@@ -295,11 +326,12 @@ int	_mtx_trylock(struct mtx *m, int opts, const char *file, int line);
 	MPASS(CURPROC != NULL);						\
 	WITNESS_EXIT((m), ((m)->mtx_flags | (opts)), __FILE__,		\
 	    __LINE__);							\
+	mtx_assert((m), MA_OWNED);					\
+	_rel_spin_lock((m));						\
 	if (((opts) & MTX_QUIET) == 0)					\
-		CTR5(KTR_LOCK, "REL %s [%p] r=%d at %s:%d",		\
-		    (m)->mtx_description, (m), (m)->mtx_recurse,	\
+		CTR5(KTR_LOCK, STR_mtx_unlock_spn,			\
+		    (m)->mtx_description, (m), (m)->mtx_recurse, 	\
 		    __FILE__, __LINE__);				\
-	_rel_spin_lock((m));						\
 } while (0)
 
 #define mtx_trylock(m)							\