Add a mutex timing flag to diag_bitmap

The MTX_UNLOCK debug lines will log for how long this thread
held the lock.

The MTX_LOCKWAIT debug lines will log how long the thread waited for the
lock to be acquired.

Bugs: Threads unlocking the mutex as part of pthread_cond_wait will
not update the time of lock value for that mutex on pthread_cond_wait
entry.

bin/varnishd/cache/cache_lck.c

@@ -37,6 +37,7 @@
 
 #include <stdlib.h>
 
+#include "vtim.h"
 #include "cache.h"
 
 /*The constability of lck depends on platform pthreads implementation */
@@ -47,6 +48,7 @@ struct ilck {
 	pthread_mutex_t		mtx;
 	int			held;
 	pthread_t		owner;
+	double			t0;
 	VTAILQ_ENTRY(ilck)	list;
 	const char		*w;
 	struct VSC_C_lck	*stat;
@@ -62,9 +64,10 @@ Lck__Lock(struct lock *lck, const char *p, const char *f, int l)
 {
 	struct ilck *ilck;
 	int r;
+	double t0, t;
 
 	CAST_OBJ_NOTNULL(ilck, lck->priv, ILCK_MAGIC);
-	if (!(cache_param->diag_bitmap & 0x18)) {
+	if (!(cache_param->diag_bitmap & 0x98)) {
 		AZ(pthread_mutex_lock(&ilck->mtx));
 		AZ(ilck->held);
 		ilck->stat->locks++;
@@ -72,6 +75,8 @@ Lck__Lock(struct lock *lck, const char *p, const char *f, int l)
 		ilck->held = 1;
 		return;
 	}
+	if (cache_param->diag_bitmap & 0x80)
+		t0 = VTIM_real();
 	r = pthread_mutex_trylock(&ilck->mtx);
 	assert(r == 0 || r == EBUSY);
 	if (r) {
@@ -83,6 +88,12 @@ Lck__Lock(struct lock *lck, const char *p, const char *f, int l)
 	} else if (cache_param->diag_bitmap & 0x8) {
 		VSL(SLT_Debug, 0, "MTX_LOCK(%s,%s,%d,%s)", p, f, l, ilck->w);
 	}
+	if (cache_param->diag_bitmap & 0x80) {
+		t = VTIM_real();
+		VSL(SLT_Debug, 0, "MTX_LOCKWAIT(%s,%s,%d,%s) %.9fs",
+		    p, f, l, ilck->w, t - t0);
+		ilck->t0 = t;
+	}
 	AZ(ilck->held);
 	ilck->stat->locks++;
 	ilck->owner = pthread_self();
@@ -110,7 +121,10 @@ Lck__Unlock(struct lock *lck, const char *p, const char *f, int l)
 	 */
 	memset(&ilck->owner, 0, sizeof ilck->owner);
 	AZ(pthread_mutex_unlock(&ilck->mtx));
-	if (cache_param->diag_bitmap & 0x8)
+	if (cache_param->diag_bitmap & 0x80)
+		VSL(SLT_Debug, 0, "MTX_UNLOCK(%s,%s,%d,%s) %.9fs",
+		    p, f, l, ilck->w, VTIM_real() - ilck->t0);
+	else if (cache_param->diag_bitmap & 0x8)
 		VSL(SLT_Debug, 0, "MTX_UNLOCK(%s,%s,%d,%s)", p, f, l, ilck->w);
 }
 
@@ -131,6 +145,8 @@ Lck__Trylock(struct lock *lck, const char *p, const char *f, int l)
 		ilck->held = 1;
 		ilck->stat->locks++;
 		ilck->owner = pthread_self();
+		if (cache_param->diag_bitmap & 0x80)
+			ilck->t0 = VTIM_real();
 	}
 	return (r);
 }

bin/varnishd/mgt/mgt_param.c

@@ -1060,6 +1060,7 @@ static const struct parspec input_parspec[] = {
 		"  0x00000010 - mutex contests.\n"
 		"  0x00000020 - waiting list.\n"
 		"  0x00000040 - object workspace.\n"
+		"  0x00000080 - mutex timing.\n"
 		"  0x00001000 - do not core-dump child process.\n"
 		"  0x00002000 - only short panic message.\n"
 		"  0x00004000 - panic to stderr.\n"
@@ -1069,7 +1070,11 @@ static const struct parspec input_parspec[] = {
 		"  0x00080000 - ban-lurker debugging.\n"
 		"  0x80000000 - do edge-detection on digest.\n"
 		"\n"
-		"Use 0x notation and do the bitor in your head :-)\n",
+		"Use 0x notation and do the bitor in your head :-)\n"
+		"\n"
+		"Note: Mutex timing will add extra overhead and "
+		"synchronization between threads, consequently changing the "
+		"locking characteristics.\n",
 		0,
 		"0", "bitmap" },
 	{ "ban_dups", tweak_bool, &mgt_param.ban_dups, 0, 0,