martin at varnish-software
Mar 12, 2012, 2:21 AM
Views: 100
Permalink
|
|
[PATCH] Log time to acquire lock when mutex logging is in effect.
|
|
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
_______________________________________________
varnish-dev mailing list
varnish-dev [at] varnish-cache
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
|
[PATCH] Log time to acquire lock when mutex logging is in effect.