Trace locks in and out with an option in normal log mode.

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, 281 insertions, 2 deletions

diff --git a/xlators/features/locks/src/common.c b/xlators/features/locks/src/common.c
index a2401d4e9..040b95469 100644
--- a/xlators/features/locks/src/common.c
+++ b/xlators/features/locks/src/common.c
@@ -118,6 +118,228 @@ __pl_inode_is_empty (pl_inode_t *pl_inode)
 }
 
 void
+pl_print_locker (char *str, int size, xlator_t *this, call_frame_t *frame)
+{
+        snprintf (str, size, "Pid=%llu, Transport=%p, Frame=%llu",
+                  (unsigned long long) frame->root->pid,
+                  (void *)frame->root->trans,
+                  (unsigned long long) frame->root->unique);
+}
+
+
+void
+pl_print_lockee (char *str, int size, fd_t *fd, loc_t *loc)
+{
+        inode_t  *inode = NULL;
+        char     *ipath = NULL;
+        int       ret = 0;
+
+        if (fd)
+                inode = fd->inode;
+        if (loc)
+                inode = loc->inode;
+
+        if (!inode) {
+                snprintf (str, size, "<nul>");
+                return;
+        }
+
+        if (loc && loc->path) {
+                ipath = strdup (loc->path);
+        } else {
+                ret = inode_path (inode, NULL, &ipath);
+                if (ret <= 0)
+                        ipath = NULL;
+        }
+
+        snprintf (str, size, "ino=%llu, fd=%p, path=%s",
+                  (unsigned long long) inode->ino, fd,
+                  ipath ? ipath : "<nul>");
+
+        if (ipath)
+                FREE (ipath);
+}
+
+
+void
+pl_print_lock (char *str, int size, int cmd, struct flock *flock)
+{
+        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, start=%llu, len=%llu, pid=%llu",
+                  cmd_str, type_str, (unsigned long long) flock->l_start,
+                  (unsigned long long) flock->l_len,
+                  (unsigned long long) flock->l_pid);
+}
+
+
+void
+pl_trace_in (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
+             int cmd, struct flock *flock)
+{
+        posix_locks_private_t  *priv = NULL;
+        char                    pl_locker[256];
+        char                    pl_lockee[256];
+        char                    pl_lock[256];
+
+        priv = this->private;
+
+        if (!priv->trace)
+                return;
+
+        pl_print_locker (pl_locker, 256, this, frame);
+        pl_print_lockee (pl_lockee, 256, fd, loc);
+        pl_print_lock (pl_lock, 256, cmd, flock);
+
+        gf_log (this->name, GF_LOG_NORMAL,
+                "[REQUEST] Locker = {%s} Lockee = {%s} Lock = {%s}",
+                pl_locker, pl_lockee, pl_lock);
+}
+
+
+void
+pl_print_verdict (char *str, int size, int op_ret, int op_errno)
+{
+        char *verdict = NULL;
+
+        if (op_ret == 0) {
+                verdict = "GRANTED";
+        } else {
+                switch (op_errno) {
+                case EAGAIN:
+                        verdict = "TRYAGAIN";
+                        break;
+                default:
+                        verdict = strerror (op_errno);
+                }
+        }
+
+        snprintf (str, size, verdict);
+}
+
+
+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)
+
+{
+        posix_locks_private_t  *priv = NULL;
+        char                    pl_locker[256];
+        char                    pl_lockee[256];
+        char                    pl_lock[256];
+        char                    verdict[32];
+
+        priv = this->private;
+
+        if (!priv->trace)
+                return;
+
+        pl_print_locker (pl_locker, 256, this, frame);
+        pl_print_lockee (pl_lockee, 256, fd, loc);
+        pl_print_lock (pl_lock, 256, cmd, flock);
+        pl_print_verdict (verdict, 32, op_ret, op_errno);
+
+        gf_log (this->name, GF_LOG_NORMAL,
+                "[%s] Locker = {%s} Lockee = {%s} Lock = {%s}",
+                verdict, pl_locker, pl_lockee, pl_lock);
+}
+
+
+void
+pl_trace_block (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
+                int cmd, struct flock *flock)
+
+{
+        posix_locks_private_t  *priv = NULL;
+        char                    pl_locker[256];
+        char                    pl_lockee[256];
+        char                    pl_lock[256];
+
+        priv = this->private;
+
+        if (!priv->trace)
+                return;
+
+        pl_print_locker (pl_locker, 256, this, frame);
+        pl_print_lockee (pl_lockee, 256, fd, loc);
+        pl_print_lock (pl_lock, 256, cmd, flock);
+
+        gf_log (this->name, GF_LOG_NORMAL,
+                "[BLOCKED] Locker = {%s} Lockee = {%s} Lock = {%s}",
+                pl_locker, pl_lockee, pl_lock);
+}
+
+
+void
+pl_trace_flush (xlator_t *this, call_frame_t *frame, fd_t *fd)
+{
+        posix_locks_private_t  *priv = NULL;
+        char                    pl_locker[256];
+        char                    pl_lockee[256];
+        pl_inode_t             *pl_inode = NULL;
+
+        priv = this->private;
+
+        if (!priv->trace)
+                return;
+
+        pl_inode = pl_inode_get (this, fd->inode);
+
+        if (pl_inode && __pl_inode_is_empty (pl_inode))
+                return;
+
+        pl_print_locker (pl_locker, 256, this, frame);
+        pl_print_lockee (pl_lockee, 256, fd, NULL);
+
+        gf_log (this->name, GF_LOG_NORMAL,
+                "[FLUSH] Locker = {%s} Lockee = {%s}",
+                pl_locker, pl_lockee);
+}
+
+void
 pl_update_refkeeper (xlator_t *this, inode_t *inode)
 {
         pl_inode_t *pl_inode  = NULL;
@@ -580,6 +802,9 @@ grant_blocked_locks (xlator_t *this, pl_inode_t *pl_inode)
         list_for_each_entry_safe (lock, tmp, &granted_list, list) {
                 list_del_init (&lock->list);
 
+                pl_trace_out (this, lock->frame, NULL, NULL, F_SETLKW,
+                              &lock->user_flock, 0, 0);
+
                 STACK_UNWIND (lock->frame, 0, 0, &lock->user_flock);
 
                 FREE (lock);
diff --git a/xlators/features/locks/src/common.h b/xlators/features/locks/src/common.h
index 4e9b30be2..bdc602f63 100644
--- a/xlators/features/locks/src/common.h
+++ b/xlators/features/locks/src/common.h
@@ -73,4 +73,37 @@ get_inodelk_count (xlator_t *this, inode_t *inode);
 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);
+
+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);
+
+void pl_trace_block (xlator_t *this, call_frame_t *frame, fd_t *fd, loc_t *loc,
+                     int cmd, struct flock *flock);
+
+void pl_trace_flush (xlator_t *this, call_frame_t *frame, fd_t *fd);
+
+void entrylk_trace_in (xlator_t *this, call_frame_t *frame, const char *volume,
+                       fd_t *fd, loc_t *loc, const char *basename,
+                       entrylk_cmd cmd, entrylk_type type);
+
+void entrylk_trace_out (xlator_t *this, call_frame_t *frame, const char *volume,
+                        fd_t *fd, loc_t *loc, const char *basename,
+                        entrylk_cmd cmd, entrylk_type type,
+                        int op_ret, int op_errno);
+
+void entrylk_trace_block (xlator_t *this, call_frame_t *frame, const char *volume,
+                          fd_t *fd, loc_t *loc, const char *basename,
+                          entrylk_cmd cmd, entrylk_type type);
+
+void
+pl_print_verdict (char *str, int size, int op_ret, int op_errno);
+
+void
+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);
+
 #endif /* __COMMON_H__ */
diff --git a/xlators/features/locks/src/locks.h b/xlators/features/locks/src/locks.h
index 0f3ab29b6..4738da068 100644
--- a/xlators/features/locks/src/locks.h
+++ b/xlators/features/locks/src/locks.h
@@ -138,6 +138,7 @@ typedef struct __pl_fd pl_fd_t;
 
 typedef struct {
         gf_boolean_t    mandatory;      /* if mandatory locking is enabled */
+        gf_boolean_t    trace;          /* trace lock requests in and out */
 } posix_locks_private_t;
 
 typedef struct {
diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c
index 3b011317c..f23716251 100644
--- a/xlators/features/locks/src/posix.c
+++ b/xlators/features/locks/src/posix.c
@@ -281,6 +281,8 @@ pl_flush (call_frame_t *frame, xlator_t *this,
                 return 0;
         }
 
+        pl_trace_flush (this, frame, fd);
+
         pthread_mutex_lock (&pl_inode->mutex);
         {
                 __delete_locks_of_owner (pl_inode, frame->root->trans,
@@ -643,6 +645,8 @@ pl_lk (call_frame_t *frame, xlator_t *this,
                 goto unwind;
         }
 
+        pl_trace_in (this, frame, fd, NULL, cmd, flock);
+
         switch (cmd) {
 
 #if F_GETLK != F_GETLK64
@@ -675,9 +679,10 @@ pl_lk (call_frame_t *frame, xlator_t *this,
                                 can_block);
 
                 if (ret == -1) {
-                        if (can_block)
+                        if (can_block) {
+                                pl_trace_block (this, frame, fd, NULL, cmd, flock);
                                 goto out;
-
+                        }
                         gf_log (this->name, GF_LOG_DEBUG, "returning EAGAIN");
                         op_ret = -1;
                         op_errno = EAGAIN;
@@ -686,6 +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_update_refkeeper (this, fd->inode);
         STACK_UNWIND_STRICT (lk, frame, op_ret, op_errno, flock);
 out:
@@ -1020,6 +1026,7 @@ init (xlator_t *this)
         posix_locks_private_t *priv = NULL;
         xlator_list_t         *trav = NULL;
         data_t                *mandatory = NULL;
+	data_t                *trace = NULL;
 
         if (!this->children || this->children->next) {
                 gf_log (this->name, GF_LOG_CRITICAL, 
@@ -1056,6 +1063,16 @@ init (xlator_t *this)
                 }
         }
 
+	trace = dict_get (this->options, "trace");
+	if (trace) {
+		if (gf_string2boolean (trace->data,
+				       &priv->trace) == -1) {
+			gf_log (this->name, GF_LOG_ERROR,
+				"'trace' takes on only boolean values.");
+			return -1;
+		}
+	}
+
         this->private = priv;
         return 0;
 }
@@ -1124,5 +1141,8 @@ struct volume_options options[] = {
         { .key  = { "mandatory-locks", "mandatory" }, 
           .type = GF_OPTION_TYPE_BOOL 
         },
+	{ .key  = { "trace" }, 
+	  .type = GF_OPTION_TYPE_BOOL 
+	},
         { .key = {NULL} },
 };