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>

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