[PATCH] Log time to acquire lock when mutex logging is in effect.

[Martin Blix Grydeland]

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

The MTX_LOCK debug lines will log how long the thread waited for the
lock to be axquired.

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 |   21 +++++++++++++++++----
 1 files changed, 17 insertions(+), 4 deletions(-)

diff --git a/bin/varnishd/cache/cache_lck.c b/bin/varnishd/cache/cache_lck.c
index 9fb34ae..8b919d2 100644
--- a/bin/varnishd/cache/cache_lck.c
+++ b/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,6 +64,7 @@ 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)) {
@@ -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 & 0x8)
+		t0 = VTIM_real();
 	r = pthread_mutex_trylock(&ilck->mtx);
 	assert(r == 0 || r == EBUSY);
 	if (r) {
@@ -80,8 +85,12 @@ Lck__Lock(struct lock *lck, const char *p, const char *f, int l)
 			VSL(SLT_Debug, 0, "MTX_CONTEST(%s,%s,%d,%s)",
 			    p, f, l, ilck->w);
 		AZ(pthread_mutex_lock(&ilck->mtx));
-	} 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 & 0x8) {
+		t = VTIM_real();
+		VSL(SLT_Debug, 0, "MTX_LOCK(%s,%s,%d,%s) %.9fs",
+		    p, f, l, ilck->w, t - t0);
+		ilck->t0 = t;
 	}
 	AZ(ilck->held);
 	ilck->stat->locks++;
@@ -110,8 +119,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)
-		VSL(SLT_Debug, 0, "MTX_UNLOCK(%s,%s,%d,%s)", p, f, l, ilck->w);
+	if (cache_param->diag_bitmap & 0x8) {
+		VSL(SLT_Debug, 0, "MTX_UNLOCK(%s,%s,%d,%s) %.9fs",
+		    p, f, l, ilck->w, VTIM_real() - ilck->t0);
+	}
 }
 
 int __match_proto__()
@@ -131,6 +142,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 & 0x8)
+			ilck->t0 = VTIM_real();
 	}
 	return (r);
 }
-- 
1.7.4.1