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 | 20 ++++++++++++++++++--
bin/varnishd/mgt/mgt_param.c | 7 ++++++-
2 files changed, 24 insertions(+), 3 deletions(-)
diff --git a/bin/varnishd/cache/cache_lck.c b/bin/varnishd/cache/cache_lck.c
index 9fb34ae..3bbbfbb 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,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);
}
diff --git a/bin/varnishd/mgt/mgt_param.c b/bin/varnishd/mgt/mgt_param.c
index 31ef010..f6493ad 100644
--- a/bin/varnishd/mgt/mgt_param.c
+++ b/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,
--
1.7.4.1
_______________________________________________
varnish-dev mailing list
[email protected]
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
