[Cluster-devel] [PATCHv2 dlm/next] fs: dlm: log plock operation time

[Alexander Aring]

This patch adds more debug logging regarding to plock operation time.
Currently plocks are handled by user space and we are waiting for a
reply of the user space. To measure this upcall and downcall again we
introduce logging information of how much time the response took and
additional posix lock information to make a match with the user space
application.

Signed-off-by: Alexander Aring <aahringo at redhat.com>
---
changes since v2:

instead using owner we printout the pid taken from
fl->fl_pid which is necessary to match with userspace
application such as dlm_controld logging.

 fs/dlm/plock.c | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

diff --git a/fs/dlm/plock.c b/fs/dlm/plock.c
index 737f185aad8d..d3115d66eece 100644
--- a/fs/dlm/plock.c
+++ b/fs/dlm/plock.c
@@ -175,6 +175,13 @@ int dlm_posix_lock(dlm_lockspace_t *lockspace, u64 number, struct file *file,
 		goto out;
 	}
 
+	log_debug(ls, "%s: op wait done %d %d %d %x %llx %llx-%llx %d %u",
+		  __func__, fl->fl_pid, fl->fl_type, cmd,
+		  ls->ls_global_id, (unsigned long long)number,
+		  (unsigned long long)fl->fl_start,
+		  (unsigned long long)fl->fl_end,
+		  op->info.rv, jiffies_to_usecs(rv));
+
 do_lock_wait:
 
 	WARN_ON(!list_empty(&op->list));
@@ -252,6 +259,7 @@ int dlm_posix_unlock(dlm_lockspace_t *lockspace, u64 number, struct file *file,
 	struct plock_op *op;
 	int rv;
 	unsigned char fl_flags = fl->fl_flags;
+	unsigned long t;
 
 	ls = dlm_find_lockspace_local(lockspace);
 	if (!ls)
@@ -295,8 +303,16 @@ int dlm_posix_unlock(dlm_lockspace_t *lockspace, u64 number, struct file *file,
 	}
 
 	send_op(op);
+	t = jiffies;
 	wait_event(recv_wq, (op->done != 0));
 
+	log_debug(ls, "%s: op wait done %d %d %x %llx %llx-%llx %d %u",
+		  __func__, fl->fl_pid, fl->fl_type,
+		  ls->ls_global_id, (unsigned long long)number,
+		  (unsigned long long)fl->fl_start,
+		  (unsigned long long)fl->fl_end,
+		  op->info.rv, jiffies_to_usecs(jiffies - t));
+
 	WARN_ON(!list_empty(&op->list));
 
 	rv = op->info.rv;
@@ -318,6 +334,7 @@ int dlm_posix_get(dlm_lockspace_t *lockspace, u64 number, struct file *file,
 {
 	struct dlm_ls *ls;
 	struct plock_op *op;
+	unsigned long t;
 	int rv;
 
 	ls = dlm_find_lockspace_local(lockspace);
@@ -343,8 +360,16 @@ int dlm_posix_get(dlm_lockspace_t *lockspace, u64 number, struct file *file,
 		op->info.owner	= (__u64)(long) fl->fl_owner;
 
 	send_op(op);
+	t = jiffies;
 	wait_event(recv_wq, (op->done != 0));
 
+	log_debug(ls, "%s: op wait done %d %d %x %llx %llx-%llx %d %u",
+		  __func__, fl->fl_pid, fl->fl_type,
+		  ls->ls_global_id, (unsigned long long)number,
+		  (unsigned long long)fl->fl_start,
+		  (unsigned long long)fl->fl_end,
+		  op->info.rv, jiffies_to_usecs(jiffies - t));
+
 	WARN_ON(!list_empty(&op->list));
 
 	/* info.rv from userspace is 1 for conflict, 0 for no-conflict,
-- 
2.31.1