[Cluster-devel] [PATCH dlm-tool 8/8] dlm_controld: add time diff for state time intervals

[Alexander Aring <aahringo@redhat.com>]

This patch adds functionality to see how long a posix lock is alive or
is in waiting or pending state. It can be used to filter out interesting
locks which are stuck in e.g. waiting state to know that a user space
process probably has contention on it. The logging information will
printout additional lock information to do more search and find to get
more information about it's corosync or kernel communication.
---
 dlm_controld/plock.c | 48 ++++++++++++++++++++++++++++++--------------
 1 file changed, 33 insertions(+), 15 deletions(-)

diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index d83a79d2..20c2a1e9 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -72,6 +72,7 @@ struct resource {
 
 struct posix_lock {
 	struct list_head	list;	   /* resource locks or waiters list */
+	struct timeval		list_time;
 	uint32_t		pid;
 	uint64_t		owner;
 	uint64_t		start;
@@ -83,6 +84,7 @@ struct posix_lock {
 
 struct lock_waiter {
 	struct list_head	list;
+	struct timeval		list_time;
 	uint32_t		flags;
 	struct dlm_plock_info	info;
 };
@@ -209,9 +211,11 @@ static uint64_t dt_usec(const struct timeval *start, const struct timeval *stop)
 }
 
 static void plock_print_lock_add_state(const struct lockspace *ls,
-				       const struct lock_waiter *w,
+				       struct lock_waiter *w,
 				       const char *state)
 {
+	gettimeofday(&w->list_time, NULL);
+
 	log_dlock(ls, "state: add %s %llx %llx-%llx %d/%u/%llx",
 		  state,
 		  (unsigned long long)w->info.number,
@@ -225,13 +229,20 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
 					 const struct lock_waiter *w,
 					 const char *state)
 {
-	log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx",
+	struct timeval now;
+	uint64_t usec;
+
+	gettimeofday(&now, NULL);
+	usec = dt_usec(&w->list_time, &now);
+
+	log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx %.3f",
 		  state,
 		  (unsigned long long)w->info.number,
 		  (unsigned long long)w->info.start,
 		  (unsigned long long)w->info.end,
 		  w->info.nodeid, w->info.pid,
-		  (unsigned long long)w->info.owner);
+		  (unsigned long long)w->info.owner,
+		  usec * 1.e-6);
 }
 
 #define plock_print_add_waiter(ls, w) \
@@ -245,23 +256,30 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
 	plock_print_lock_clear_state(ls, w, "pending")
 
 static void plock_print_add_plock(const struct lockspace *ls,
-				  const struct posix_lock *plock)
+				  struct posix_lock *po)
 {
-	log_dlock(ls, "state: add plock NA %llx-%llx %d/%u/%llx",
-		  (unsigned long long)plock->start,
-		  (unsigned long long)plock->end,
-		  plock->nodeid, plock->pid,
-		  (unsigned long long)plock->owner);
+	gettimeofday(&po->list_time, NULL);
+	log_dlock(ls, "state: add plock %llx-%llx %d/%u/%llx %.3f",
+		  (unsigned long long)po->start,
+		  (unsigned long long)po->end,
+		  po->nodeid, po->pid,
+		  (unsigned long long)po->owner);
 }
 
 static void plock_print_del_plock(const struct lockspace *ls,
-				  const struct posix_lock *plock)
+				  const struct posix_lock *po)
 {
-	log_dlock(ls, "state: del plock NA %llx-%llx %d/%u/%llx",
-		  (unsigned long long)plock->start,
-		  (unsigned long long)plock->end,
-		  plock->nodeid, plock->pid,
-		  (unsigned long long)plock->owner);
+	struct timeval now;
+	uint64_t usec;
+
+	gettimeofday(&now, NULL);
+	usec = dt_usec(&po->list_time, &now);
+	log_dlock(ls, "state: clear plock %llx-%llx %d/%u/%llx %.3f",
+		  (unsigned long long)po->start,
+		  (unsigned long long)po->end,
+		  po->nodeid, po->pid,
+		  (unsigned long long)po->owner,
+		  usec * 1.e-6);
 }
 
 static struct resource * rb_search_plock_resource(struct lockspace *ls, uint64_t number)
-- 
2.31.1