diff options
| -rw-r--r-- | libglusterfs/src/latency.c | 100 | ||||
| -rw-r--r-- | libglusterfs/src/stack.c | 93 | ||||
| -rw-r--r-- | libglusterfs/src/stack.h | 57 | ||||
| -rwxr-xr-x | tests/bugs/bug-844688.t | 37 |
4 files changed, 202 insertions, 85 deletions
diff --git a/libglusterfs/src/latency.c b/libglusterfs/src/latency.c index 9fe76efa040..b22f729500c 100644 --- a/libglusterfs/src/latency.c +++ b/libglusterfs/src/latency.c @@ -26,87 +26,87 @@ gf_set_fop_from_fn_pointer (call_frame_t *frame, struct xlator_fops *fops, void { glusterfs_fop_t fop = -1; - if (fops->stat == *(fop_stat_t *)fn) + if (fops->stat == *(fop_stat_t *)&fn) fop = GF_FOP_STAT; - else if (fops->readlink == *(fop_readlink_t *)fn) + else if (fops->readlink == *(fop_readlink_t *)&fn) fop = GF_FOP_READLINK; - else if (fops->mknod == *(fop_mknod_t *)fn) + else if (fops->mknod == *(fop_mknod_t *)&fn) fop = GF_FOP_MKNOD; - else if (fops->mkdir == *(fop_mkdir_t *)fn) + else if (fops->mkdir == *(fop_mkdir_t *)&fn) fop = GF_FOP_MKDIR; - else if (fops->unlink == *(fop_unlink_t *)fn) + else if (fops->unlink == *(fop_unlink_t *)&fn) fop = GF_FOP_UNLINK; - else if (fops->rmdir == *(fop_rmdir_t *)fn) + else if (fops->rmdir == *(fop_rmdir_t *)&fn) fop = GF_FOP_RMDIR; - else if (fops->symlink == *(fop_symlink_t *)fn) + else if (fops->symlink == *(fop_symlink_t *)&fn) fop = GF_FOP_SYMLINK; - else if (fops->rename == *(fop_rename_t *)fn) + else if (fops->rename == *(fop_rename_t *)&fn) fop = GF_FOP_RENAME; - else if (fops->link == *(fop_link_t *)fn) + else if (fops->link == *(fop_link_t *)&fn) fop = GF_FOP_LINK; - else if (fops->truncate == *(fop_truncate_t *)fn) + else if (fops->truncate == *(fop_truncate_t *)&fn) fop = GF_FOP_TRUNCATE; - else if (fops->open == *(fop_open_t *)fn) + else if (fops->open == *(fop_open_t *)&fn) fop = GF_FOP_OPEN; - else if (fops->readv == *(fop_readv_t *)fn) + else if (fops->readv == *(fop_readv_t *)&fn) fop = GF_FOP_READ; - else if (fops->writev == *(fop_writev_t *)fn) + else if (fops->writev == *(fop_writev_t *)&fn) fop = GF_FOP_WRITE; - else if (fops->statfs == *(fop_statfs_t *)fn) + else if (fops->statfs == *(fop_statfs_t *)&fn) fop = GF_FOP_STATFS; - else if (fops->flush == *(fop_flush_t *)fn) + else if (fops->flush == *(fop_flush_t *)&fn) fop = GF_FOP_FLUSH; - else if (fops->fsync == *(fop_fsync_t *)fn) + else if (fops->fsync == *(fop_fsync_t *)&fn) fop = GF_FOP_FSYNC; - else if (fops->setxattr == *(fop_setxattr_t *)fn) + else if (fops->setxattr == *(fop_setxattr_t *)&fn) fop = GF_FOP_SETXATTR; - else if (fops->getxattr == *(fop_getxattr_t *)fn) + else if (fops->getxattr == *(fop_getxattr_t *)&fn) fop = GF_FOP_GETXATTR; - else if (fops->removexattr == *(fop_removexattr_t *)fn) + else if (fops->removexattr == *(fop_removexattr_t *)&fn) fop = GF_FOP_REMOVEXATTR; - else if (fops->opendir == *(fop_opendir_t *)fn) + else if (fops->opendir == *(fop_opendir_t *)&fn) fop = GF_FOP_OPENDIR; - else if (fops->fsyncdir == *(fop_fsyncdir_t *)fn) + else if (fops->fsyncdir == *(fop_fsyncdir_t *)&fn) fop = GF_FOP_FSYNCDIR; - else if (fops->access == *(fop_access_t *)fn) + else if (fops->access == *(fop_access_t *)&fn) fop = GF_FOP_ACCESS; - else if (fops->create == *(fop_create_t *)fn) + else if (fops->create == *(fop_create_t *)&fn) fop = GF_FOP_CREATE; - else if (fops->ftruncate == *(fop_ftruncate_t *)fn) + else if (fops->ftruncate == *(fop_ftruncate_t *)&fn) fop = GF_FOP_FTRUNCATE; - else if (fops->fstat == *(fop_fstat_t *)fn) + else if (fops->fstat == *(fop_fstat_t *)&fn) fop = GF_FOP_FSTAT; - else if (fops->lk == *(fop_lk_t *)fn) + else if (fops->lk == *(fop_lk_t *)&fn) fop = GF_FOP_LK; - else if (fops->lookup == *(fop_lookup_t *)fn) + else if (fops->lookup == *(fop_lookup_t *)&fn) fop = GF_FOP_LOOKUP; - else if (fops->readdir == *(fop_readdir_t *)fn) + else if (fops->readdir == *(fop_readdir_t *)&fn) fop = GF_FOP_READDIR; - else if (fops->inodelk == *(fop_inodelk_t *)fn) + else if (fops->inodelk == *(fop_inodelk_t *)&fn) fop = GF_FOP_INODELK; - else if (fops->finodelk == *(fop_finodelk_t *)fn) + else if (fops->finodelk == *(fop_finodelk_t *)&fn) fop = GF_FOP_FINODELK; - else if (fops->entrylk == *(fop_entrylk_t *)fn) + else if (fops->entrylk == *(fop_entrylk_t *)&fn) fop = GF_FOP_ENTRYLK; - else if (fops->fentrylk == *(fop_fentrylk_t *)fn) + else if (fops->fentrylk == *(fop_fentrylk_t *)&fn) fop = GF_FOP_FENTRYLK; - else if (fops->xattrop == *(fop_xattrop_t *)fn) + else if (fops->xattrop == *(fop_xattrop_t *)&fn) fop = GF_FOP_XATTROP; - else if (fops->fxattrop == *(fop_fxattrop_t *)fn) + else if (fops->fxattrop == *(fop_fxattrop_t *)&fn) fop = GF_FOP_FXATTROP; - else if (fops->fgetxattr == *(fop_fgetxattr_t *)fn) + else if (fops->fgetxattr == *(fop_fgetxattr_t *)&fn) fop = GF_FOP_FGETXATTR; - else if (fops->fsetxattr == *(fop_fsetxattr_t *)fn) + else if (fops->fsetxattr == *(fop_fsetxattr_t *)&fn) fop = GF_FOP_FSETXATTR; - else if (fops->rchecksum == *(fop_rchecksum_t *)fn) + else if (fops->rchecksum == *(fop_rchecksum_t *)&fn) fop = GF_FOP_RCHECKSUM; - else if (fops->setattr == *(fop_setattr_t *)fn) + else if (fops->setattr == *(fop_setattr_t *)&fn) fop = GF_FOP_SETATTR; - else if (fops->fsetattr == *(fop_fsetattr_t *)fn) + else if (fops->fsetattr == *(fop_fsetattr_t *)&fn) fop = GF_FOP_FSETATTR; - else if (fops->readdirp == *(fop_readdirp_t *)fn) + else if (fops->readdirp == *(fop_readdirp_t *)&fn) fop = GF_FOP_READDIRP; - else if (fops->getspec == *(fop_getspec_t *)fn) + else if (fops->getspec == *(fop_getspec_t *)&fn) fop = GF_FOP_GETSPEC; else fop = -1; @@ -136,6 +136,22 @@ gf_update_latency (call_frame_t *frame) lat->mean = lat->mean + (elapsed - lat->mean) / lat->count; } +void +gf_latency_begin (call_frame_t *frame, void *fn) +{ + gf_set_fop_from_fn_pointer (frame, frame->this->fops, fn); + + gettimeofday (&frame->begin, NULL); +} + + +void +gf_latency_end (call_frame_t *frame) +{ + gettimeofday (&frame->end, NULL); + + gf_update_latency (frame); +} void gf_proc_dump_latency_info (xlator_t *xl) @@ -156,6 +172,8 @@ gf_proc_dump_latency_info (xlator_t *xl) xl->latencies[i].count, xl->latencies[i].total); } + + memset (xl->latencies, 0, sizeof (xl->latencies)); } diff --git a/libglusterfs/src/stack.c b/libglusterfs/src/stack.c index 5349eaa0b01..37b338f51cb 100644 --- a/libglusterfs/src/stack.c +++ b/libglusterfs/src/stack.c @@ -26,6 +26,44 @@ int call_frames_count (call_frame_t *call_frame) return count; } +call_frame_t * +create_frame (xlator_t *xl, call_pool_t *pool) +{ + call_stack_t *stack = NULL; + + if (!xl || !pool) { + return NULL; + } + + stack = mem_get0 (pool->stack_mem_pool); + if (!stack) + return NULL; + + stack->pool = pool; + stack->frames.root = stack; + stack->frames.this = xl; + stack->ctx = xl->ctx; + + if (stack->ctx->measure_latency) { + if (gettimeofday (&stack->tv, NULL) == -1) + gf_log ("stack", GF_LOG_ERROR, "gettimeofday () failed." + " (%s)", strerror (errno)); + memcpy (&stack->frames.begin, &stack->tv, sizeof (stack->tv)); + } + + LOCK (&pool->lock); + { + list_add (&stack->all_frames, &pool->all_frames); + pool->cnt++; + } + UNLOCK (&pool->lock); + + LOCK_INIT (&stack->frames.lock); + LOCK_INIT (&stack->stack_lock); + + return &stack->frames; +} + void gf_proc_dump_call_frame (call_frame_t *call_frame, const char *key_buf,...) { @@ -34,6 +72,7 @@ gf_proc_dump_call_frame (call_frame_t *call_frame, const char *key_buf,...) va_list ap; call_frame_t my_frame; int ret = -1; + char timestr[256] = {0,}; if (!call_frame) return; @@ -47,15 +86,21 @@ gf_proc_dump_call_frame (call_frame_t *call_frame, const char *key_buf,...) va_end(ap); ret = TRY_LOCK(&call_frame->lock); - if (ret) { - gf_log("", GF_LOG_WARNING, "Unable to dump call frame" - " errno: %s", strerror (errno)); - return; - } + if (ret) + goto out; memcpy(&my_frame, call_frame, sizeof(my_frame)); UNLOCK(&call_frame->lock); + if (my_frame.this->ctx->measure_latency) { + gf_time_fmt (timestr, sizeof timestr, my_frame.begin.tv_sec, + gf_timefmt_FT); + snprintf (timestr + strlen (timestr), + sizeof timestr - strlen (timestr), + ".%"GF_PRI_SUSECONDS, my_frame.begin.tv_usec); + gf_proc_dump_write("frame-creation-time", "%s", timestr); + } + gf_proc_dump_write("ref_count", "%d", my_frame.ref_count); gf_proc_dump_write("translator", "%s", my_frame.this->name); gf_proc_dump_write("complete", "%d", my_frame.complete); @@ -73,6 +118,14 @@ gf_proc_dump_call_frame (call_frame_t *call_frame, const char *key_buf,...) if (my_frame.unwind_to) gf_proc_dump_write("unwind_to", "%s", my_frame.unwind_to); + + ret = 0; +out: + if (ret) { + gf_proc_dump_write("Unable to dump the frame information", + "(Lock acquisition failed) %p", my_frame); + return; + } } @@ -83,6 +136,7 @@ gf_proc_dump_call_stack (call_stack_t *call_stack, const char *key_buf,...) va_list ap; call_frame_t *trav; int32_t cnt, i; + char timestr[256] = {0,}; if (!call_stack) return; @@ -96,6 +150,15 @@ gf_proc_dump_call_stack (call_stack_t *call_stack, const char *key_buf,...) vsnprintf(prefix, GF_DUMP_MAX_BUF_LEN, key_buf, ap); va_end(ap); + if (call_stack->ctx->measure_latency) { + gf_time_fmt (timestr, sizeof timestr, call_stack->tv.tv_sec, + gf_timefmt_FT); + snprintf (timestr + strlen (timestr), + sizeof timestr - strlen (timestr), + ".%"GF_PRI_SUSECONDS, call_stack->tv.tv_usec); + gf_proc_dump_write("callstack-creation-time", "%s", timestr); + } + gf_proc_dump_write("uid", "%d", call_stack->uid); gf_proc_dump_write("gid", "%d", call_stack->gid); gf_proc_dump_write("pid", "%d", call_stack->pid); @@ -129,19 +192,18 @@ gf_proc_dump_pending_frames (call_pool_t *call_pool) call_stack_t *trav = NULL; int i = 1; int ret = -1; + gf_boolean_t section_added = _gf_true; if (!call_pool) return; ret = TRY_LOCK (&(call_pool->lock)); - if (ret) { - gf_log("", GF_LOG_WARNING, "Unable to dump call pool" - " errno: %d", errno); - return; - } + if (ret) + goto out; gf_proc_dump_add_section("global.callpool"); + section_added = _gf_true; gf_proc_dump_write("callpool_address","%p", call_pool); gf_proc_dump_write("callpool.cnt","%d", call_pool->cnt); @@ -152,6 +214,17 @@ gf_proc_dump_pending_frames (call_pool_t *call_pool) i++; } UNLOCK (&(call_pool->lock)); + + ret = 0; +out: + if (ret) { + if (_gf_false == section_added) + gf_proc_dump_add_section("global.callpool"); + gf_proc_dump_write("Unable to dump the callpool", + "(Lock acquisition failed) %p", + call_pool); + } + return; } void diff --git a/libglusterfs/src/stack.h b/libglusterfs/src/stack.h index b14b08dbb9a..a91b635e47e 100644 --- a/libglusterfs/src/stack.h +++ b/libglusterfs/src/stack.h @@ -101,11 +101,13 @@ struct _call_stack_t { uint16_t ngrps; uint32_t groups[GF_MAX_AUX_GROUPS]; gf_lkowner_t lk_owner; + glusterfs_ctx_t *ctx; call_frame_t frames; int32_t op; int8_t type; + struct timeval tv; }; @@ -122,11 +124,10 @@ struct _call_stack_t { struct xlator_fops; void -gf_set_fop_from_fn_pointer (call_frame_t *frame, struct xlator_fops *fops, - void *fn); +gf_latency_begin (call_frame_t *frame, void *fn); void -gf_update_latency (call_frame_t *frame); +gf_latency_end (call_frame_t *frame); static inline void FRAME_DESTROY (call_frame_t *frame) @@ -236,6 +237,7 @@ STACK_RESET (call_stack_t *stack) _new->wind_from = __FUNCTION__; \ _new->wind_to = #fn; \ _new->unwind_to = #rfn; \ + \ LOCK_INIT (&_new->lock); \ LOCK(&frame->root->stack_lock); \ { \ @@ -249,6 +251,8 @@ STACK_RESET (call_stack_t *stack) UNLOCK(&frame->root->stack_lock); \ old_THIS = THIS; \ THIS = obj; \ + if (frame->this->ctx->measure_latency) \ + gf_latency_begin (_new, fn); \ fn (_new, obj, params); \ THIS = old_THIS; \ } while (0) @@ -302,6 +306,8 @@ STACK_RESET (call_stack_t *stack) fn##_cbk = rfn; \ old_THIS = THIS; \ THIS = obj; \ + if (obj->ctx->measure_latency) \ + gf_latency_begin (_new, fn); \ fn (_new, obj, params); \ THIS = old_THIS; \ } while (0) @@ -328,6 +334,8 @@ STACK_RESET (call_stack_t *stack) THIS = _parent->this; \ frame->complete = _gf_true; \ frame->unwind_from = __FUNCTION__; \ + if (frame->this->ctx->measure_latency) \ + gf_latency_end (frame); \ fn (_parent, frame->cookie, _parent->this, params); \ THIS = old_THIS; \ } while (0) @@ -355,6 +363,8 @@ STACK_RESET (call_stack_t *stack) THIS = _parent->this; \ frame->complete = _gf_true; \ frame->unwind_from = __FUNCTION__; \ + if (frame->this->ctx->measure_latency) \ + gf_latency_end (frame); \ fn (_parent, frame->cookie, _parent->this, params); \ THIS = old_THIS; \ } while (0) @@ -391,6 +401,15 @@ copy_frame (call_frame_t *frame) newstack->frames.root = newstack; newstack->pool = oldstack->pool; newstack->lk_owner = oldstack->lk_owner; + newstack->ctx = oldstack->ctx; + + if (newstack->ctx->measure_latency) { + if (gettimeofday (&newstack->tv, NULL) == -1) + gf_log ("stack", GF_LOG_ERROR, "gettimeofday () failed." + " (%s)", strerror (errno)); + memcpy (&newstack->frames.begin, &newstack->tv, + sizeof (newstack->tv)); + } LOCK_INIT (&newstack->frames.lock); LOCK_INIT (&newstack->stack_lock); @@ -405,39 +424,9 @@ copy_frame (call_frame_t *frame) return &newstack->frames; } - -static inline call_frame_t * -create_frame (xlator_t *xl, call_pool_t *pool) -{ - call_stack_t *stack = NULL; - - if (!xl || !pool) { - return NULL; - } - - stack = mem_get0 (pool->stack_mem_pool); - if (!stack) - return NULL; - - stack->pool = pool; - stack->frames.root = stack; - stack->frames.this = xl; - - LOCK (&pool->lock); - { - list_add (&stack->all_frames, &pool->all_frames); - pool->cnt++; - } - UNLOCK (&pool->lock); - - LOCK_INIT (&stack->frames.lock); - LOCK_INIT (&stack->stack_lock); - - return &stack->frames; -} - void gf_proc_dump_pending_frames(call_pool_t *call_pool); void gf_proc_dump_pending_frames_to_dict (call_pool_t *call_pool, dict_t *dict); +call_frame_t *create_frame (xlator_t *xl, call_pool_t *pool); gf_boolean_t __is_fuse_call (call_frame_t *frame); #endif /* _STACK_H */ diff --git a/tests/bugs/bug-844688.t b/tests/bugs/bug-844688.t new file mode 100755 index 00000000000..154d35e48b7 --- /dev/null +++ b/tests/bugs/bug-844688.t @@ -0,0 +1,37 @@ +#!/bin/bash + +. $(dirname $0)/../include.rc +. $(dirname $0)/../volume.rc + +cleanup; + +TEST glusterd +TEST pidof glusterd +TEST $CLI volume create $V0 $H0:$B0/brick0 +TEST $CLI volume start $V0 + +sleep 5 + +TEST glusterfs -s $H0 --volfile-id $V0 $M0 + +mount_pid=$(get_mount_process_pid $V0); +# enable dumping of call stack creation and frame creation times in statedump +kill -USR2 $mount_pid; + +TEST touch $M0/touchfile; +(dd if=/dev/urandom of=$M0/file bs=5K 2>/dev/null 1>/dev/null)& +back_pid=$!; +statedump_file=$(generate_mount_statedump $V0); +grep "callstack-creation-time" $statedump_file 2>/dev/null 1>/dev/null; +TEST [ $? -eq 0 ]; +grep "frame-creation-time" $statedump_file 2>/dev/null 1>/dev/null; +TEST [ $? -eq 0 ]; + +kill -SIGTERM $back_pid; +wait >/dev/null 2>&1; + +TEST rm -f $M0/touchfile $M0/file; +TEST umount $M0; + +rm -f $statedumpdir/glusterdump.$mount_pid.*; +cleanup |