From 3490d999794b2303fcfdfacf93f844a1bd816b54 Mon Sep 17 00:00:00 2001 From: Asad Sajjad Ahmed Date: Thu, 7 Sep 2023 14:33:29 +0200 Subject: [PATCH] varnishd: add lock duration Our instrumented locks lacks a way to tell how long a lock was held before released. Just looking at the number of time the lock was taken is not enough. Some locks are more expensive than others (held for longer). This commit adds duration to each instrumented lock given in microsecond resolution. Signed-off-by: Asad Sajjad Ahmed --- bin/varnishd/cache/cache_lck.c | 6 ++++++ lib/libvsc/VSC_lck.vsc | 4 ++++ 2 files changed, 10 insertions(+) diff --git a/bin/varnishd/cache/cache_lck.c b/bin/varnishd/cache/cache_lck.c index ee3d9a47386..9bf4b884904 100644 --- a/bin/varnishd/cache/cache_lck.c +++ b/bin/varnishd/cache/cache_lck.c @@ -54,6 +54,7 @@ struct ilck { pthread_t owner; const char *w; struct VSC_lck *stat; + vtim_dur taken_us; }; /*--------------------------------------------------------------------*/ @@ -127,6 +128,7 @@ Lck__Lock(struct lock *lck, const char *p, int l) ilck->stat->dbg_busy++; ilck->stat->locks++; ilck->owner = pthread_self(); + ilck->taken_us = 1e6L * VTIM_mono(); ilck->held = 1; } @@ -141,6 +143,7 @@ Lck__Unlock(struct lock *lck, const char *p, int l) AN(lck); CAST_OBJ_NOTNULL(ilck, lck->priv, ILCK_MAGIC); assert(pthread_equal(ilck->owner, pthread_self())); + ilck->stat->dur_us += 1e6L * VTIM_mono() - ilck->taken_us; AN(ilck->held); ilck->held = 0; /* @@ -180,6 +183,7 @@ Lck__Trylock(struct lock *lck, const char *p, int l) ilck->held = 1; ilck->stat->locks++; ilck->owner = pthread_self(); + ilck->taken_us = 1e6L * VTIM_mono(); } else if (DO_DEBUG(DBG_LCK)) ilck->stat->dbg_try_fail++; return (r); @@ -234,6 +238,7 @@ Lck_CondWaitUntil(pthread_cond_t *cond, struct lock *lck, vtim_real when) CAST_OBJ_NOTNULL(ilck, lck->priv, ILCK_MAGIC); AN(ilck->held); assert(pthread_equal(ilck->owner, pthread_self())); + ilck->stat->dur_us += 1e6L * VTIM_mono() - ilck->taken_us; ilck->held = 0; if (when == 0) { errno = pthread_cond_wait(cond, &ilck->mtx); @@ -278,6 +283,7 @@ Lck_CondWaitUntil(pthread_cond_t *cond, struct lock *lck, vtim_real when) AZ(ilck->held); ilck->held = 1; ilck->owner = pthread_self(); + ilck->taken_us = 1e6L * VTIM_mono(); return (errno); } diff --git a/lib/libvsc/VSC_lck.vsc b/lib/libvsc/VSC_lck.vsc index ee7ff64fdb0..c1c48dea375 100644 --- a/lib/libvsc/VSC_lck.vsc +++ b/lib/libvsc/VSC_lck.vsc @@ -34,6 +34,10 @@ :level: debug :oneliner: Lock Operations +.. varnish_vsc:: dur_us + :type: counter + :level: debug + :oneliner: Lock duration .. varnish_vsc:: dbg_busy :type: counter