Add a new KTR type KTR_CONTENTION, and use it in the mutex code to

log the start and end of periods during which mtx_lock() is waiting
to acquire a sleep mutex. The log message includes the file and
line of both the waiter and the holder.

Reviewed by:	jhb, jake

1 files changed, 20 insertions, 0 deletions

diff --git a/sys/kern/kern_mutex.c b/sys/kern/kern_mutex.c
index bd94bdcbf970..982b3761c2df 100644
--- a/sys/kern/kern_mutex.c
+++ b/sys/kern/kern_mutex.c
@@ -471,6 +471,9 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 #if defined(SMP) && defined(ADAPTIVE_MUTEXES)
 	struct thread *owner;
 #endif
+#ifdef KTR
+	int cont_logged = 0;
+#endif
 
 	if ((m->mtx_lock & MTX_FLAGMASK) == (uintptr_t)td) {
 		m->mtx_recurse++;
@@ -588,6 +591,16 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 			else
 				TAILQ_INSERT_TAIL(&m->mtx_blocked, td, td_blkq);
 		}
+#ifdef KTR
+		if (!cont_logged) {
+			CTR6(KTR_CONTENTION,
+			    "contention: %p at %s:%d wants %s, taken by %s:%d",
+			    td, file, line, m->mtx_object.lo_name,
+			    WITNESS_FILE(&m->mtx_object),
+			    WITNESS_LINE(&m->mtx_object));
+			cont_logged = 1;
+		}
+#endif
 
 		/*
 		 * Save who we're blocked on.
@@ -613,6 +626,13 @@ _mtx_lock_sleep(struct mtx *m, int opts, const char *file, int line)
 		mtx_unlock_spin(&sched_lock);
 	}
 
+#ifdef KTR
+	if (cont_logged) {
+		CTR4(KTR_CONTENTION,
+		    "contention end: %s acquired by %p at %s:%d",
+		    m->mtx_object.lo_name, td, file, line);
+	}
+#endif
 	return;
 }