From 04de4b6063617d4ad31b31fb0d24fe2242deb7f0 Mon Sep 17 00:00:00 2001 From: Anand Avati Date: Fri, 16 Oct 2009 16:21:09 +0000 Subject: 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 BUG: 306 (Enhance locks to aid debugging) URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=306 --- xlators/features/locks/src/common.c | 221 ++++++++++++++++++++++++++++++++++++ xlators/features/locks/src/common.h | 11 ++ xlators/features/locks/src/locks.h | 1 + xlators/features/locks/src/posix.c | 24 +++- 4 files changed, 256 insertions(+), 1 deletion(-) (limited to 'xlators/features/locks') diff --git a/xlators/features/locks/src/common.c b/xlators/features/locks/src/common.c index 11841e92d..3681c31f5 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, ""); + 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 : ""); + + 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 78de8432f..9f3b0cf0c 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 fe1333504..f649dd609 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 b1eb7e435..74740151a 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} }, }; -- cgit