summaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorRaghavendra Bhat <raghavendra@redhat.com>2012-10-15 11:09:18 +0530
committerAnand Avati <avati@redhat.com>2013-02-06 12:18:49 -0800
commit6b292ff33fd842c77cd076e67b7f042d9f0cbedf (patch)
tree303aac8c9def1801129db6f013a8af3221dcbd8f
parentd831290debf7cc5741c30233d05aa18c9a59e99e (diff)
libglusterfs/core: dump frame and callstack creation times in statedump
Change-Id: I3772602ac264cbca490d77a0343038297faee7df BUG: 844688 Signed-off-by: Raghavendra Bhat <raghavendra@redhat.com> Reviewed-on: http://review.gluster.org/4087 Tested-by: Gluster Build System <jenkins@build.gluster.com> Reviewed-by: Anand Avati <avati@redhat.com>
-rw-r--r--libglusterfs/src/latency.c100
-rw-r--r--libglusterfs/src/stack.c93
-rw-r--r--libglusterfs/src/stack.h57
-rwxr-xr-xtests/bugs/bug-844688.t37
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