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 <aahri...@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

Reply via email to