locks: trace support

'option trace on' will trace all locks and unlocks in the logfile
under 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, 256 insertions, 1 deletions

diff --git a/xlators/features/locks/src/common.c b/xlators/features/locks/src/common.c
index 11841e92d07..3681c31f5d5 100644
--- a/xlators/features/locks/src/common.c
+++ b/xlators/features/locks/src/common.c
@@ -532,6 +532,9 @@ grant_blocked_locks (xlator_t *this, pl_inode_t *pl_inode, gf_lk_domain_t dom)
 	list_for_each_entry_safe (lock, tmp, &granted_list, list) {
 		list_del_init (&lock->list);
 
+                pl_trace_out (this, lock->frame, NULL, F_SETLKW,
+                              &lock->user_flock, 0, 0);
+
 		STACK_UNWIND (lock->frame, 0, 0, &lock->user_flock);
 
 		FREE (lock);
@@ -604,3 +607,221 @@ pl_getlk (pl_inode_t *pl_inode, posix_lock_t *lock, gf_lk_domain_t dom)
 
 	return conf;
 }
+
+
+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;
+        }
+
+        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, 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, NULL);
+        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, 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, NULL);
+        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, 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, NULL);
+        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);
+}
+
diff --git a/xlators/features/locks/src/common.h b/xlators/features/locks/src/common.h
index 78de8432fad..9f3b0cf0c2f 100644
--- a/xlators/features/locks/src/common.h
+++ b/xlators/features/locks/src/common.h
@@ -51,4 +51,15 @@ void __destroy_lock (posix_lock_t *);
 
 void pl_update_refkeeper (xlator_t *this, inode_t *inode);
 
+void pl_trace_in (xlator_t *this, call_frame_t *frame, fd_t *fd, int cmd,
+                  struct flock *flock);
+
+void pl_trace_out (xlator_t *this, call_frame_t *frame, fd_t *fd, 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, int cmd,
+                     struct flock *flock);
+
+void pl_trace_flush (xlator_t *this, call_frame_t *frame, fd_t *fd);
+
 #endif /* __COMMON_H__ */
diff --git a/xlators/features/locks/src/locks.h b/xlators/features/locks/src/locks.h
index fe1333504ad..f649dd609b0 100644
--- a/xlators/features/locks/src/locks.h
+++ b/xlators/features/locks/src/locks.h
@@ -108,6 +108,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;
 
 
diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c
index b1eb7e43518..74740151afa 100644
--- a/xlators/features/locks/src/posix.c
+++ b/xlators/features/locks/src/posix.c
@@ -286,6 +286,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,
@@ -644,6 +646,8 @@ pl_lk (call_frame_t *frame, xlator_t *this,
 		goto unwind;
 	}
 
+        pl_trace_in (this, frame, fd, cmd, flock);
+
 	switch (cmd) {
 
 #if F_GETLK != F_GETLK64
@@ -676,8 +680,10 @@ pl_lk (call_frame_t *frame, xlator_t *this,
 				can_block, GF_LOCK_POSIX);
 
 		if (ret == -1) {
-			if (can_block)
+			if (can_block) {
+                                pl_trace_block (this, frame, fd, cmd, flock);
 				goto out;
+                        }
 
 			gf_log (this->name, GF_LOG_DEBUG, "returning EAGAIN");
 			op_ret = -1;
@@ -687,6 +693,8 @@ pl_lk (call_frame_t *frame, xlator_t *this,
 	}
 
 unwind:
+        pl_trace_out (this, frame, fd, cmd, flock, op_ret, op_errno);
+
         pl_update_refkeeper (this, fd->inode);
 	STACK_UNWIND (frame, op_ret, op_errno, flock);
 out:
@@ -775,6 +783,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, 
@@ -811,6 +820,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;
 }
@@ -875,5 +894,8 @@ struct volume_options options[] = {
 	{ .key  = { "mandatory-locks", "mandatory" }, 
 	  .type = GF_OPTION_TYPE_BOOL 
 	},
+	{ .key  = { "trace" }, 
+	  .type = GF_OPTION_TYPE_BOOL 
+	},
 	{ .key = {NULL} },
 };