From 08327b6a6bdb7a3807a9d279b6d5f99686d13b99 Mon Sep 17 00:00:00 2001 From: Pavan Sondur Date: Wed, 28 Oct 2009 17:04:05 +0000 Subject: Print entrylks in and out if option trace is on. Signed-off-by: Anand V. Avati BUG: 306 (Enhance locks to aid debugging) URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=306 --- xlators/features/locks/src/entrylk.c | 140 ++++++++++++++++++++++++++++++++++- 1 file changed, 136 insertions(+), 4 deletions(-) (limited to 'xlators/features/locks/src/entrylk.c') diff --git a/xlators/features/locks/src/entrylk.c b/xlators/features/locks/src/entrylk.c index fdfa2ba86..3b96646ed 100644 --- a/xlators/features/locks/src/entrylk.c +++ b/xlators/features/locks/src/entrylk.c @@ -149,6 +149,125 @@ names_equal (const char *n1, const char *n2) return (n1 == NULL && n2 == NULL) || (n1 && n2 && !strcmp (n1, n2)); } +void +pl_print_entrylk (char *str, int size, entrylk_cmd cmd, entrylk_type type, + const char *basename, const char *domain) +{ + char *cmd_str = NULL; + char *type_str = NULL; + + switch (cmd) { + case ENTRYLK_LOCK: + cmd_str = "LOCK"; + break; + + case ENTRYLK_LOCK_NB: + cmd_str = "LOCK_NB"; + break; + + case ENTRYLK_UNLOCK: + cmd_str = "UNLOCK"; + break; + + default: + cmd_str = "UNKNOWN"; + break; + } + + switch (type) { + case ENTRYLK_RDLCK: + type_str = "READ"; + break; + case ENTRYLK_WRLCK: + type_str = "WRITE"; + break; + default: + type_str = "UNKNOWN"; + break; + } + + snprintf (str, size, "cmd=%s, type=%s, basename=%s, domain: %s", + cmd_str, type_str, basename, domain); +} + + +void +entrylk_trace_in (xlator_t *this, call_frame_t *frame, const char *domain, + fd_t *fd, loc_t *loc, const char *basename, + entrylk_cmd cmd, entrylk_type type) +{ + posix_locks_private_t *priv = NULL; + char pl_locker[256]; + char pl_lockee[256]; + char pl_entrylk[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_entrylk (pl_entrylk, 256, cmd, type, basename, domain); + + gf_log (this->name, GF_LOG_NORMAL, + "[REQUEST] Locker = {%s} Lockee = {%s} Lock = {%s}", + pl_locker, pl_lockee, pl_entrylk); +} + + +void +entrylk_trace_out (xlator_t *this, call_frame_t *frame, const char *domain, + fd_t *fd, loc_t *loc, const char *basename, + entrylk_cmd cmd, entrylk_type type, int op_ret, int op_errno) +{ + posix_locks_private_t *priv = NULL; + char pl_locker[256]; + char pl_lockee[256]; + char pl_entrylk[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_entrylk (pl_entrylk, 256, cmd, type, basename, domain); + 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_entrylk); +} + + +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) + +{ + posix_locks_private_t *priv = NULL; + char pl_locker[256]; + char pl_lockee[256]; + char pl_entrylk[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_entrylk (pl_entrylk, 256, cmd, type, basename, volume); + + gf_log (this->name, GF_LOG_NORMAL, + "[BLOCKED] Locker = {%s} Lockee = {%s} Lock = {%s}", + pl_locker, pl_lockee, pl_entrylk); +} + /** * __find_most_matching_lock - find the lock struct which most matches in order of: * lock on the exact basename || @@ -360,6 +479,10 @@ grant_blocked_entry_locks (xlator_t *this, pl_inode_t *pl_inode, list_for_each_entry_safe (lock, tmp, &granted_list, blocked_locks) { list_del_init (&lock->blocked_locks); + entrylk_trace_out (this, lock->frame, NULL, NULL, NULL, + lock->basename, ENTRYLK_LOCK, lock->type, + 0, 0); + STACK_UNWIND_STRICT (entrylk, lock->frame, 0, 0); FREE (lock->basename); @@ -431,7 +554,7 @@ unlock: int pl_common_entrylk (call_frame_t *frame, xlator_t *this, const char *volume, inode_t *inode, const char *basename, - entrylk_cmd cmd, entrylk_type type) + entrylk_cmd cmd, entrylk_type type, loc_t *loc, fd_t *fd) { int32_t op_ret = -1; int32_t op_errno = 0; @@ -462,6 +585,8 @@ pl_common_entrylk (call_frame_t *frame, xlator_t *this, goto out; } + entrylk_trace_in (this, frame, volume, fd, loc, basename, cmd, type); + pid = frame->root->pid; transport = frame->root->trans; @@ -536,8 +661,15 @@ pl_common_entrylk (call_frame_t *frame, xlator_t *this, out: pl_update_refkeeper (this, inode); if (unwind) { + entrylk_trace_out (this, frame, volume, fd, loc, basename, + cmd, type, op_ret, op_errno); + STACK_UNWIND_STRICT (entrylk, frame, op_ret, op_errno); - } + } else { + entrylk_trace_block (this, frame, volume, fd, loc, basename, + cmd, type); + } + return 0; } @@ -554,7 +686,7 @@ pl_entrylk (call_frame_t *frame, xlator_t *this, entrylk_cmd cmd, entrylk_type type) { - pl_common_entrylk (frame, this, volume, loc->inode, basename, cmd, type); + pl_common_entrylk (frame, this, volume, loc->inode, basename, cmd, type, loc, NULL); return 0; } @@ -572,7 +704,7 @@ pl_fentrylk (call_frame_t *frame, xlator_t *this, entrylk_cmd cmd, entrylk_type type) { - pl_common_entrylk (frame, this, volume, fd->inode, basename, cmd, type); + pl_common_entrylk (frame, this, volume, fd->inode, basename, cmd, type, NULL, fd); return 0; } -- cgit