Print inodelks in and out if option trace is on.

Signed-off-by: Anand V. Avati <avati@dev.gluster.com>

BUG: 306 (Enhance locks to aid debugging)
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=306

4 files changed, 96 insertions, 18 deletions

diff --git a/xlators/features/locks/src/common.c b/xlators/features/locks/src/common.c
index 040b95469..fb011fe6a 100644
--- a/xlators/features/locks/src/common.c
+++ b/xlators/features/locks/src/common.c
@@ -218,7 +218,7 @@ pl_print_lock (char *str, int size, int cmd, struct flock *flock)
 
 void
 pl_trace_in (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-             int cmd, struct flock *flock)
+             int cmd, struct flock *flock, const char *domain)
 {
         posix_locks_private_t  *priv = NULL;
         char                    pl_locker[256];
@@ -232,7 +232,10 @@ pl_trace_in (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
 
         pl_print_locker (pl_locker, 256, this, frame);
         pl_print_lockee (pl_lockee, 256, fd, loc);
-        pl_print_lock (pl_lock, 256, cmd, flock);
+        if (domain)
+                pl_print_inodelk (pl_lock, 256, cmd, flock, domain);
+        else
+                pl_print_lock (pl_lock, 256, cmd, flock);
 
         gf_log (this->name, GF_LOG_NORMAL,
                 "[REQUEST] Locker = {%s} Lockee = {%s} Lock = {%s}",
@@ -263,7 +266,7 @@ pl_print_verdict (char *str, int size, int op_ret, int op_errno)
 
 void
 pl_trace_out (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-              int cmd, struct flock *flock, int op_ret, int op_errno)
+              int cmd, struct flock *flock, int op_ret, int op_errno, const char *domain)
 
 {
         posix_locks_private_t  *priv = NULL;
@@ -279,7 +282,11 @@ pl_trace_out (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
 
         pl_print_locker (pl_locker, 256, this, frame);
         pl_print_lockee (pl_lockee, 256, fd, loc);
-        pl_print_lock (pl_lock, 256, cmd, flock);
+        if (domain)
+                pl_print_inodelk (pl_lock, 256, cmd, flock, domain);
+        else
+                pl_print_lock (pl_lock, 256, cmd, flock);
+
         pl_print_verdict (verdict, 32, op_ret, op_errno);
 
         gf_log (this->name, GF_LOG_NORMAL,
@@ -290,7 +297,7 @@ pl_trace_out (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
 
 void
 pl_trace_block (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-                int cmd, struct flock *flock)
+                int cmd, struct flock *flock, const char *domain)
 
 {
         posix_locks_private_t  *priv = NULL;
@@ -305,7 +312,10 @@ pl_trace_block (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
 
         pl_print_locker (pl_locker, 256, this, frame);
         pl_print_lockee (pl_lockee, 256, fd, loc);
-        pl_print_lock (pl_lock, 256, cmd, flock);
+        if (domain)
+                pl_print_inodelk (pl_lock, 256, cmd, flock, domain);
+        else
+                pl_print_lock (pl_lock, 256, cmd, flock);
 
         gf_log (this->name, GF_LOG_NORMAL,
                 "[BLOCKED] Locker = {%s} Lockee = {%s} Lock = {%s}",
@@ -803,7 +813,7 @@ grant_blocked_locks (xlator_t *this, pl_inode_t *pl_inode)
                 list_del_init (&lock->list);
 
                 pl_trace_out (this, lock->frame, NULL, NULL, F_SETLKW,
-                              &lock->user_flock, 0, 0);
+                              &lock->user_flock, 0, 0, NULL);
 
                 STACK_UNWIND (lock->frame, 0, 0, &lock->user_flock);
 
diff --git a/xlators/features/locks/src/common.h b/xlators/features/locks/src/common.h
index bdc602f63..292d82ce8 100644
--- a/xlators/features/locks/src/common.h
+++ b/xlators/features/locks/src/common.h
@@ -74,13 +74,13 @@ int32_t
 get_entrylk_count (xlator_t *this, inode_t *inode);
 
 void pl_trace_in (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-                  int cmd, struct flock *flock);
+                  int cmd, struct flock *flock, const char *domain);
 
 void pl_trace_out (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-                   int cmd, struct flock *flock, int op_ret, int op_errno);
+                   int cmd, struct flock *flock, int op_ret, int op_errno, const char *domain);
 
 void pl_trace_block (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
-                     int cmd, struct flock *flock);
+                     int cmd, struct flock *flock, const char *domain);
 
 void pl_trace_flush (xlator_t *this, call_frame_t *frame, fd_t *fd);
 
@@ -106,4 +106,7 @@ pl_print_lockee (char *str, int size, fd_t *fd, loc_t *loc);
 void
 pl_print_locker (char *str, int size, xlator_t *this, call_frame_t *frame);
 
+void
+pl_print_inodelk (char *str, int size, int cmd, struct flock *flock, const char *domain);
+
 #endif /* __COMMON_H__ */
diff --git a/xlators/features/locks/src/inodelk.c b/xlators/features/locks/src/inodelk.c
index 78e4154bc..6c89ed7d1 100644
--- a/xlators/features/locks/src/inodelk.c
+++ b/xlators/features/locks/src/inodelk.c
@@ -55,6 +55,61 @@ inodelk_type_conflict (pl_inode_lock_t *l1, pl_inode_lock_t *l2)
 	return 0;
 }
 
+void
+pl_print_inodelk (char *str, int size, int cmd, struct flock *flock, const char *domain)
+{
+        char *cmd_str = NULL;
+        char *type_str = NULL;
+
+        switch (cmd) {
+#if F_GETLK != F_GETLK64
+        case F_GETLK64:
+#endif
+        case F_GETLK:
+                cmd_str = "GETLK";
+                break;
+
+#if F_SETLK != F_SETLK64
+        case F_SETLK64:
+#endif
+        case F_SETLK:
+                cmd_str = "SETLK";
+                break;
+
+#if F_SETLKW != F_SETLKW64
+        case F_SETLKW64:
+#endif
+        case F_SETLKW:
+                cmd_str = "SETLKW";
+                break;
+
+        default:
+                cmd_str = "UNKNOWN";
+                break;
+        }
+
+        switch (flock->l_type) {
+        case F_RDLCK:
+                type_str = "READ";
+                break;
+        case F_WRLCK:
+                type_str = "WRITE";
+                break;
+        case F_UNLCK:
+                type_str = "UNLOCK";
+                break;
+        default:
+                type_str = "UNKNOWN";
+                break;
+        }
+
+        snprintf (str, size, "cmd=%s, type=%s, domain: %s, start=%llu, len=%llu, pid=%llu",
+                  cmd_str, type_str, domain,
+                  (unsigned long long) flock->l_start,
+                  (unsigned long long) flock->l_len,
+                  (unsigned long long) flock->l_pid);
+}
+
 /* Determine if the two inodelks overlap reach other's lock regions */
 static int
 inodelk_overlap (pl_inode_lock_t *l1, pl_inode_lock_t *l2)
@@ -269,6 +324,10 @@ __grant_blocked_inode_locks (xlator_t *this, pl_inode_t *pl_inode, pl_dom_list_t
                                 bl->user_flock.l_start,
                                 bl->user_flock.l_len);
 
+                        pl_trace_out (this, bl->frame, NULL, NULL, F_SETLKW,
+                                      &bl->user_flock, 0, 0, bl->volume);
+
+
                         STACK_UNWIND_STRICT (inodelk, bl->frame, 0, 0);
                 }
         }
@@ -435,7 +494,8 @@ new_inode_lock (struct flock *flock, transport_t *transport, pid_t client_pid, c
 /* Common inodelk code called form pl_inodelk and pl_finodelk */
 int
 pl_common_inodelk (call_frame_t *frame, xlator_t *this,
-                   const char *volume, inode_t *inode, int32_t cmd, struct flock *flock)
+                   const char *volume, inode_t *inode, int32_t cmd,
+                   struct flock *flock, loc_t *loc, fd_t *fd)
 {
 	int32_t op_ret   = -1;
 	int32_t op_errno = 0;
@@ -456,6 +516,8 @@ pl_common_inodelk (call_frame_t *frame, xlator_t *this,
 		goto unwind;
 	}
 
+        pl_trace_in (this, frame, fd, loc, cmd, flock, volume);
+
 	transport  = frame->root->trans;
 	client_pid = frame->root->pid;
 
@@ -504,9 +566,11 @@ pl_common_inodelk (call_frame_t *frame, xlator_t *this,
                                       can_block, dom);
 
 		if (ret < 0) {
-                        if (can_block)
+                        if (can_block) {
+                                pl_trace_block (this, frame, fd, loc,
+                                                cmd, flock, volume);
 				goto out;
-
+                        }
 			gf_log (this->name, GF_LOG_TRACE, "returning EAGAIN");
 			op_errno = -ret;
 			__destroy_inode_lock (reqlock);
@@ -527,6 +591,7 @@ pl_common_inodelk (call_frame_t *frame, xlator_t *this,
 
 unwind:
         pl_update_refkeeper (this, inode);
+        pl_trace_out (this, frame, fd, loc, cmd, flock, op_ret, op_errno, volume);
         STACK_UNWIND_STRICT (inodelk, frame, op_ret, op_errno);
 out:
         return 0;
@@ -537,7 +602,7 @@ pl_inodelk (call_frame_t *frame, xlator_t *this,
             const char *volume, loc_t *loc, int32_t cmd, struct flock *flock)
 {
 
-        pl_common_inodelk (frame, this, volume, loc->inode, cmd, flock);
+        pl_common_inodelk (frame, this, volume, loc->inode, cmd, flock, loc, NULL);
 
         return 0;
 }
@@ -547,7 +612,7 @@ pl_finodelk (call_frame_t *frame, xlator_t *this,
              const char *volume, fd_t *fd, int32_t cmd, struct flock *flock)
 {
 
-        pl_common_inodelk (frame, this, volume, fd->inode, cmd, flock);
+        pl_common_inodelk (frame, this, volume, fd->inode, cmd, flock, NULL, fd);
 
         return 0;
 
diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c
index f23716251..21f1870b8 100644
--- a/xlators/features/locks/src/posix.c
+++ b/xlators/features/locks/src/posix.c
@@ -645,7 +645,7 @@ pl_lk (call_frame_t *frame, xlator_t *this,
                 goto unwind;
         }
 
-        pl_trace_in (this, frame, fd, NULL, cmd, flock);
+        pl_trace_in (this, frame, fd, NULL, cmd, flock, NULL);
 
         switch (cmd) {
 
@@ -680,7 +680,7 @@ pl_lk (call_frame_t *frame, xlator_t *this,
 
                 if (ret == -1) {
                         if (can_block) {
-                                pl_trace_block (this, frame, fd, NULL, cmd, flock);
+                                pl_trace_block (this, frame, fd, NULL, cmd, flock, NULL);
                                 goto out;
                         }
                         gf_log (this->name, GF_LOG_DEBUG, "returning EAGAIN");
@@ -691,7 +691,7 @@ pl_lk (call_frame_t *frame, xlator_t *this,
         }
 
 unwind:
-        pl_trace_out (this, frame, fd, NULL, cmd, flock, op_ret, op_errno);
+        pl_trace_out (this, frame, fd, NULL, cmd, flock, op_ret, op_errno, NULL);
         pl_update_refkeeper (this, fd->inode);
         STACK_UNWIND_STRICT (lk, frame, op_ret, op_errno, flock);
 out: