From 02bd1bcd2ad2387d37b5905ebd66ed92b9ee5b9f Mon Sep 17 00:00:00 2001
From: Ian Dowse <iedowse@FreeBSD.org>
Date: Mon, 26 Aug 2002 18:39:38 +0000
Subject: [PATCH] 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
---
 sys/kern/kern_mutex.c     | 20 ++++++++++++++++++++
 sys/kern/subr_turnstile.c | 20 ++++++++++++++++++++
 sys/sys/ktr.h             |  3 ++-
 3 files changed, 42 insertions(+), 1 deletion(-)

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;
 }
 
diff --git a/sys/kern/subr_turnstile.c b/sys/kern/subr_turnstile.c
index bd94bdcbf970..982b3761c2df 100644
--- a/sys/kern/subr_turnstile.c
+++ b/sys/kern/subr_turnstile.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;
 }
 
diff --git a/sys/sys/ktr.h b/sys/sys/ktr.h
index 3b552a97b45d..41220a3dacb1 100644
--- a/sys/sys/ktr.h
+++ b/sys/sys/ktr.h
@@ -71,7 +71,8 @@
 #define KTR_VM		0x00100000		/* The virtual memory system */
 #define KTR_WITNESS	0x00200000
 #define	KTR_RUNQ	0x00400000		/* Run queue */
-#define	KTR_ALL		0x007fffff
+#define	KTR_CONTENTION	0x00800000		/* Lock contention */
+#define	KTR_ALL		0x00ffffff
 
 /*
  * Trace classes which can be assigned to particular use at compile time