stack: change gettimeofday() to clock_gettime()

For achieving the above, needed below changes too.

* more sanity into how 'frame->op' is assigned.
* infra to have 'stats' as separate section in 'xlator_t' structure

Updates #137

Change-Id: I36679bf9577f3ed00a695b4e7d92870dcb3db8e1
Signed-off-by: Amar Tumballi <amarts@redhat.com>

12 files changed, 216 insertions, 231 deletions

diff --git a/libglusterfs/src/common-utils.h b/libglusterfs/src/common-utils.h
index 18ab56aeb9b..1954892ff8f 100644
--- a/libglusterfs/src/common-utils.h
+++ b/libglusterfs/src/common-utils.h
@@ -422,6 +422,14 @@ BIT_VALUE (unsigned char *array, unsigned int index)
         } while (0)
 #endif
 
+#define GF_ABORT(msg)                                                   \
+        do {                                                            \
+                gf_msg_callingfn ("", GF_LOG_CRITICAL, 0,               \
+                                  LG_MSG_ASSERTION_FAILED,              \
+                                  "Assertion failed: " msg);            \
+                abort();                                                \
+        } while (0)
+
 #define GF_UUID_ASSERT(u) \
         if (gf_uuid_is_null (u))\
                 GF_ASSERT (!"uuid null");
diff --git a/libglusterfs/src/latency.c b/libglusterfs/src/latency.c
index 1d75f5b98ce..d0039a1f730 100644
--- a/libglusterfs/src/latency.c
+++ b/libglusterfs/src/latency.c
@@ -21,146 +21,43 @@
 #include "statedump.h"
 #include "libglusterfs-messages.h"
 
-static int gf_set_fop_from_fn_pointer_warning;
-void
-gf_set_fop_from_fn_pointer (call_frame_t *frame, struct xlator_fops *fops, void *fn)
-{
-        glusterfs_fop_t fop = -1;
-
-        if (fops->stat == *(fop_stat_t *)&fn)
-                fop = GF_FOP_STAT;
-        else if (fops->readlink == *(fop_readlink_t *)&fn)
-                fop = GF_FOP_READLINK;
-        else if (fops->mknod == *(fop_mknod_t *)&fn)
-                fop = GF_FOP_MKNOD;
-        else if (fops->mkdir == *(fop_mkdir_t *)&fn)
-                fop = GF_FOP_MKDIR;
-        else if (fops->unlink == *(fop_unlink_t *)&fn)
-                fop = GF_FOP_UNLINK;
-        else if (fops->rmdir == *(fop_rmdir_t *)&fn)
-                fop = GF_FOP_RMDIR;
-        else if (fops->symlink == *(fop_symlink_t *)&fn)
-                fop = GF_FOP_SYMLINK;
-        else if (fops->rename == *(fop_rename_t *)&fn)
-                fop = GF_FOP_RENAME;
-        else if (fops->link == *(fop_link_t *)&fn)
-                fop = GF_FOP_LINK;
-        else if (fops->truncate == *(fop_truncate_t *)&fn)
-                fop = GF_FOP_TRUNCATE;
-        else if (fops->open == *(fop_open_t *)&fn)
-                fop = GF_FOP_OPEN;
-        else if (fops->readv == *(fop_readv_t *)&fn)
-                fop = GF_FOP_READ;
-        else if (fops->writev == *(fop_writev_t *)&fn)
-                fop = GF_FOP_WRITE;
-        else if (fops->statfs == *(fop_statfs_t *)&fn)
-                fop = GF_FOP_STATFS;
-        else if (fops->flush == *(fop_flush_t *)&fn)
-                fop = GF_FOP_FLUSH;
-        else if (fops->fsync == *(fop_fsync_t *)&fn)
-                fop = GF_FOP_FSYNC;
-        else if (fops->setxattr == *(fop_setxattr_t *)&fn)
-                fop = GF_FOP_SETXATTR;
-        else if (fops->getxattr == *(fop_getxattr_t *)&fn)
-                fop = GF_FOP_GETXATTR;
-        else if (fops->removexattr == *(fop_removexattr_t *)&fn)
-                fop = GF_FOP_REMOVEXATTR;
-        else if (fops->opendir == *(fop_opendir_t *)&fn)
-                fop = GF_FOP_OPENDIR;
-        else if (fops->fsyncdir == *(fop_fsyncdir_t *)&fn)
-                fop = GF_FOP_FSYNCDIR;
-        else if (fops->access == *(fop_access_t *)&fn)
-                fop = GF_FOP_ACCESS;
-        else if (fops->create == *(fop_create_t *)&fn)
-                fop = GF_FOP_CREATE;
-        else if (fops->ftruncate == *(fop_ftruncate_t *)&fn)
-                fop = GF_FOP_FTRUNCATE;
-        else if (fops->fstat == *(fop_fstat_t *)&fn)
-                fop = GF_FOP_FSTAT;
-        else if (fops->lk == *(fop_lk_t *)&fn)
-                fop = GF_FOP_LK;
-        else if (fops->lookup == *(fop_lookup_t *)&fn)
-                fop = GF_FOP_LOOKUP;
-        else if (fops->readdir == *(fop_readdir_t *)&fn)
-                fop = GF_FOP_READDIR;
-        else if (fops->inodelk == *(fop_inodelk_t *)&fn)
-                fop = GF_FOP_INODELK;
-        else if (fops->finodelk == *(fop_finodelk_t *)&fn)
-                fop = GF_FOP_FINODELK;
-        else if (fops->entrylk == *(fop_entrylk_t *)&fn)
-                fop = GF_FOP_ENTRYLK;
-        else if (fops->fentrylk == *(fop_fentrylk_t *)&fn)
-                fop = GF_FOP_FENTRYLK;
-        else if (fops->xattrop == *(fop_xattrop_t *)&fn)
-                fop = GF_FOP_XATTROP;
-        else if (fops->fxattrop == *(fop_fxattrop_t *)&fn)
-                fop = GF_FOP_FXATTROP;
-        else if (fops->fgetxattr == *(fop_fgetxattr_t *)&fn)
-                fop = GF_FOP_FGETXATTR;
-        else if (fops->fsetxattr == *(fop_fsetxattr_t *)&fn)
-                fop = GF_FOP_FSETXATTR;
-        else if (fops->rchecksum == *(fop_rchecksum_t *)&fn)
-                fop = GF_FOP_RCHECKSUM;
-        else if (fops->setattr == *(fop_setattr_t *)&fn)
-                fop = GF_FOP_SETATTR;
-        else if (fops->fsetattr == *(fop_fsetattr_t *)&fn)
-                fop = GF_FOP_FSETATTR;
-        else if (fops->readdirp == *(fop_readdirp_t *)&fn)
-                fop = GF_FOP_READDIRP;
-        else if (fops->getspec == *(fop_getspec_t *)&fn)
-                fop = GF_FOP_GETSPEC;
-        else if (fops->ipc == *(fop_ipc_t *)&fn)
-                fop = GF_FOP_IPC;
-        else {
-                fop = GF_FOP_NULL;
-                GF_LOG_OCCASIONALLY(gf_set_fop_from_fn_pointer_warning,
-                                    "latency",
-                                    GF_LOG_WARNING,
-                                    "Unknown FOP type");
-        }
-
-        frame->op   = fop;
-}
-
-
 void
 gf_update_latency (call_frame_t *frame)
 {
         double elapsed;
-        struct timeval *begin, *end;
+        struct timespec *begin, *end;
 
         fop_latency_t *lat;
 
         begin = &frame->begin;
         end   = &frame->end;
 
-        elapsed = (end->tv_sec - begin->tv_sec) * 1e6
-                + (end->tv_usec - begin->tv_usec);
-
-        lat = &frame->this->latencies[frame->op];
+        if (!(begin->tv_sec && end->tv_sec))
+                goto out;
 
-        lat->total += elapsed;
-        lat->count++;
-        lat->mean = lat->mean + (elapsed - lat->mean) / lat->count;
-}
+        elapsed = (end->tv_sec - begin->tv_sec) * 1e9
+                + (end->tv_nsec - begin->tv_nsec);
 
-void
-gf_latency_begin (call_frame_t *frame, void *fn)
-{
-        gf_set_fop_from_fn_pointer (frame, frame->this->fops, fn);
+        /* Can happen mostly at initiator xlator, as STACK_WIND/UNWIND macros
+           set it right anyways for those frames */
+        if (!frame->op)
+                frame->op = frame->root->op;
 
-        gettimeofday (&frame->begin, NULL);
-}
+        lat = &frame->this->stats.interval.latencies[frame->op];
 
+        if (lat->max < elapsed)
+                lat->max = elapsed;
 
-void
-gf_latency_end (call_frame_t *frame)
-{
-        gettimeofday (&frame->end, NULL);
+        if (lat->min > elapsed)
+                lat->min = elapsed;
 
-        gf_update_latency (frame);
+        lat->total += elapsed;
+        lat->count++;
+out:
+        return;
 }
 
+
 void
 gf_proc_dump_latency_info (xlator_t *xl)
 {
@@ -175,13 +72,26 @@ gf_proc_dump_latency_info (xlator_t *xl)
                 gf_proc_dump_build_key (key, key_prefix, "%s",
                                         (char *)gf_fop_list[i]);
 
+                fop_latency_t *lat = &xl->stats.interval.latencies[i];
+
+                /* Doesn't make sense to continue if there are no fops
+                   came in the given interval */
+                if (!lat->count)
+                        continue;
+
                 gf_proc_dump_write (key, "%.03f,%"PRId64",%.03f",
-                                    xl->latencies[i].mean,
-                                    xl->latencies[i].count,
-                                    xl->latencies[i].total);
+                                    (lat->total / lat->count), lat->count,
+                                    lat->total);
         }
 
-        memset (xl->latencies, 0, sizeof (xl->latencies));
+        memset (xl->stats.interval.latencies, 0,
+                sizeof (xl->stats.interval.latencies));
+
+        /* make sure 'min' is set to high value, so it would be
+           properly set later */
+        for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+                xl->stats.interval.latencies[i].min = 0xffffffff;
+        }
 }
 
 
diff --git a/libglusterfs/src/latency.h b/libglusterfs/src/latency.h
index 81acbf48478..132520c1263 100644
--- a/libglusterfs/src/latency.h
+++ b/libglusterfs/src/latency.h
@@ -14,11 +14,9 @@
 #include "glusterfs.h"
 
 typedef struct fop_latency {
-        uint64_t min;           /* min time for the call (microseconds) */
-        uint64_t max;           /* max time for the call (microseconds) */
+        double min;           /* min time for the call (microseconds) */
+        double max;           /* max time for the call (microseconds) */
 	double total;           /* total time (microseconds) */
-        double std;             /* standard deviation */
-        double mean;            /* mean (microseconds) */
         uint64_t count;
 } fop_latency_t;
 
diff --git a/libglusterfs/src/logging.h b/libglusterfs/src/logging.h
index fd9a36d15c2..6e433e203f9 100644
--- a/libglusterfs/src/logging.h
+++ b/libglusterfs/src/logging.h
@@ -25,6 +25,7 @@
 #define GF_PRI_NLINK       PRIu32
 #define GF_PRI_SECOND      "ld"
 #define GF_PRI_SUSECONDS   "06d"
+#define GF_PRI_SNSECONDS   "09ld"
 #define GF_PRI_USEC        "d"
 #else
 #define GF_PRI_FSBLK       PRIu64
@@ -33,6 +34,7 @@
 #define GF_PRI_NLINK       PRIu32
 #define GF_PRI_SECOND      "lu"
 #define GF_PRI_SUSECONDS   "06ld"
+#define GF_PRI_SNSECONDS   "09ld"
 #define GF_PRI_USEC        "ld"
 #endif
 #define GF_PRI_BLKSIZE     PRId32
diff --git a/libglusterfs/src/stack.c b/libglusterfs/src/stack.c
index 6977814ec69..5527814a19d 100644
--- a/libglusterfs/src/stack.c
+++ b/libglusterfs/src/stack.c
@@ -43,15 +43,12 @@ create_frame (xlator_t *xl, call_pool_t *pool)
         stack->pool = pool;
         stack->ctx = xl->ctx;
 
-        if (stack->ctx->measure_latency) {
-                if (gettimeofday (&stack->tv, NULL) == -1)
-                        gf_msg ("stack", GF_LOG_ERROR, errno,
-                                LG_MSG_GETTIMEOFDAY_FAILED,
-                                "gettimeofday () failed");
-                memcpy (&frame->begin, &stack->tv, sizeof (stack->tv));
+        if (frame->root->ctx->measure_latency) {
+                timespec_now (&stack->tv);
+                memcpy (&frame->begin, &stack->tv,
+                        sizeof (stack->tv));
         }
 
-
         LOCK (&pool->lock);
         {
                 list_add (&stack->all_frames, &pool->all_frames);
@@ -92,19 +89,26 @@ gf_proc_dump_call_frame (call_frame_t *call_frame, const char *key_buf,...)
         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,
+        if (my_frame.root->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);
+                          sizeof (timestr) - strlen (timestr),
+                          ".%"GF_PRI_SNSECONDS, my_frame.begin.tv_nsec);
                 gf_proc_dump_write("frame-creation-time", "%s", timestr);
+                gf_proc_dump_write("timings", "%ld.%"GF_PRI_SNSECONDS
+                                   " -> %ld.%"GF_PRI_SNSECONDS,
+                                   my_frame.begin.tv_sec,
+                                   my_frame.begin.tv_nsec,
+                                   my_frame.end.tv_sec,
+                                   my_frame.end.tv_nsec);
         }
 
         gf_proc_dump_write("frame", "%p", call_frame);
         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);
+
         if (my_frame.parent)
                 gf_proc_dump_write("parent", "%s", my_frame.parent->this->name);
 
@@ -150,14 +154,12 @@ gf_proc_dump_call_stack (call_stack_t *call_stack, const char *key_buf,...)
         va_end(ap);
 
         cnt = call_frames_count (call_stack);
-        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_time_fmt (timestr, sizeof (timestr), call_stack->tv.tv_sec,
+                     gf_timefmt_FT);
+        snprintf (timestr + strlen (timestr),
+                  sizeof (timestr) - strlen (timestr),
+                  ".%"GF_PRI_SNSECONDS, call_stack->tv.tv_nsec);
         gf_proc_dump_write("callstack-creation-time", "%s", timestr);
-        }
 
         gf_proc_dump_write("stack", "%p", call_stack);
         gf_proc_dump_write("uid", "%d", call_stack->uid);
@@ -165,6 +167,8 @@ gf_proc_dump_call_stack (call_stack_t *call_stack, const char *key_buf,...)
         gf_proc_dump_write("pid", "%d", call_stack->pid);
         gf_proc_dump_write("unique", "%Ld", call_stack->unique);
         gf_proc_dump_write("lk-owner", "%s", lkowner_utoa (&call_stack->lk_owner));
+        gf_proc_dump_write("ctime", "%lld.%"GF_PRI_SNSECONDS,
+                           call_stack->tv.tv_sec, call_stack->tv.tv_nsec);
 
         if (call_stack->type == GF_OP_TYPE_FOP)
                 gf_proc_dump_write("op", "%s",
@@ -230,6 +234,7 @@ gf_proc_dump_call_frame_to_dict (call_frame_t *call_frame,
 {
         int             ret = -1;
         char            key[GF_DUMP_MAX_BUF_LEN] = {0,};
+        char            msg[GF_DUMP_MAX_BUF_LEN] = {0,};
         call_frame_t    tmp_frame = {0,};
 
         if (!call_frame || !dict)
@@ -259,6 +264,18 @@ gf_proc_dump_call_frame_to_dict (call_frame_t *call_frame,
         if (ret)
                 return;
 
+        if (tmp_frame.root->ctx->measure_latency) {
+                memset (key, 0, sizeof (key));
+                snprintf (key, sizeof (key), "%s.timings", prefix);
+                snprintf (msg, sizeof (msg), "%ld.%"GF_PRI_SNSECONDS
+                          " -> %ld.%"GF_PRI_SNSECONDS,
+                          tmp_frame.begin.tv_sec, tmp_frame.begin.tv_nsec,
+                          tmp_frame.end.tv_sec, tmp_frame.end.tv_nsec);
+                ret = dict_set_str (dict, key, msg);
+                if (ret)
+                        return;
+        }
+
         if (tmp_frame.parent) {
                 memset (key, 0, sizeof (key));
                 snprintf (key, sizeof (key), "%s.parent", prefix);
diff --git a/libglusterfs/src/stack.h b/libglusterfs/src/stack.h
index 856a9a4786e..8a617377bc7 100644
--- a/libglusterfs/src/stack.h
+++ b/libglusterfs/src/stack.h
@@ -32,6 +32,7 @@ typedef struct call_pool call_pool_t;
 #include "lkowner.h"
 #include "client_t.h"
 #include "libglusterfs-messages.h"
+#include "timespec.h"
 
 #define NFS_PID 1
 #define LOW_PRIO_PROC_PID -1
@@ -72,9 +73,9 @@ struct _call_frame {
         void         *cookie;      /* unique cookie */
         gf_boolean_t  complete;
 
-        glusterfs_fop_t op;
-        struct timeval begin;      /* when this frame was created */
-        struct timeval end;        /* when this frame completed */
+        glusterfs_fop_t  op;
+        struct timespec  begin;      /* when this frame was created */
+        struct timespec  end;        /* when this frame completed */
         const char      *wind_from;
         const char      *wind_to;
         const char      *unwind_from;
@@ -112,7 +113,7 @@ struct _call_stack {
 
         int32_t                       op;
         int8_t                        type;
-        struct timeval                tv;
+        struct timespec               tv;
         xlator_t                     *err_xl;
         int32_t                       error;
 };
@@ -129,18 +130,17 @@ struct _call_stack {
 
 
 struct xlator_fops;
+void gf_update_latency (call_frame_t *frame);
 
-void
-gf_latency_begin (call_frame_t *frame, void *fn);
-
-void
-gf_latency_end (call_frame_t *frame);
 
 static inline void
 FRAME_DESTROY (call_frame_t *frame)
 {
         void *local = NULL;
 
+        if (frame->root->ctx->measure_latency)
+                gf_update_latency (frame);
+
         list_del_init (&frame->frames);
         if (frame->local) {
                 local = frame->local;
@@ -225,6 +225,18 @@ STACK_RESET (call_stack_t *stack)
         } while (0);                                                   \
 
 
+/* NOTE: make sure to keep this as an macro, mainly because, we need 'fn'
+   field here to be the proper fn ptr, so its address is valid entry in
+   'xlator_fops' struct.
+   To understand this, check the `xlator.h:struct xlator_fops`, and then
+   see a STACK_WIND call, which generally calls `subvol->fops->fop`, so
+   the address offset should give the index */
+
+/* +1 is required as 0 means NULL fop, and we don't have a variable for it */
+#define get_fop_index_from_fn(xl, fn)                                   \
+        (1 + (((long)&(fn) - (long)&((xl)->fops->stat)) / sizeof (void *)))
+
+
 /* make a call without switching frames */
 #define STACK_WIND_TAIL(frame, obj, fn, params ...)                     \
         do {                                                            \
@@ -295,7 +307,8 @@ STACK_RESET (call_stack_t *stack)
                               frame->root, old_THIS->name,              \
                               THIS->name);                              \
                 if (obj->ctx->measure_latency)                          \
-                        gf_latency_begin (_new, fn);                    \
+                        timespec_now (&_new->begin);                    \
+                _new->op = get_fop_index_from_fn ((_new->this), (fn));  \
                 fn (_new, obj, params);                                 \
                 THIS = old_THIS;                                        \
         } while (0)
@@ -304,9 +317,9 @@ STACK_RESET (call_stack_t *stack)
 #define STACK_UNWIND STACK_UNWIND_STRICT
 
 /* return from function in type-safe way */
-#define STACK_UNWIND_STRICT(op, frame, op_ret, op_errno, params ...)    \
+#define STACK_UNWIND_STRICT(fop, frame, op_ret, op_errno, params ...)   \
         do {                                                            \
-                fop_##op##_cbk_t      fn = NULL;                        \
+                fop_##fop##_cbk_t      fn = NULL;                       \
                 call_frame_t *_parent = NULL;                           \
                 xlator_t     *old_THIS = NULL;                          \
                                                                         \
@@ -329,7 +342,7 @@ STACK_RESET (call_stack_t *stack)
                                       frame->root, THIS->name,          \
                                       (int32_t)(op_ret));               \
                 }                                                       \
-                fn = (fop_##op##_cbk_t )frame->ret;                     \
+                fn = (fop_##fop##_cbk_t)frame->ret;                     \
                 _parent = frame->parent;                                \
                 LOCK(&frame->root->stack_lock);                         \
                 {                                                       \
@@ -348,8 +361,12 @@ 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);                         \
+                if (frame->this->ctx->measure_latency) {                \
+                        timespec_now (&frame->end);                     \
+                        /* required for top most xlator */              \
+                        if (_parent->ret == NULL)                       \
+                                timespec_now (&_parent->end);           \
+                }                                                       \
                 fn (_parent, frame->cookie, _parent->this, op_ret,      \
                     op_errno, params);                                  \
                 THIS = old_THIS;                                        \
@@ -454,10 +471,7 @@ copy_frame (call_frame_t *frame)
         newstack->ctx = oldstack->ctx;
 
         if (newstack->ctx->measure_latency) {
-                if (gettimeofday (&newstack->tv, NULL) == -1)
-                        gf_msg ("stack", GF_LOG_ERROR, errno,
-                                LG_MSG_GETTIMEOFDAY_FAILED,
-                                "gettimeofday () failed.");
+                timespec_now (&newstack->tv);
                 memcpy (&newframe->begin, &newstack->tv,
                         sizeof (newstack->tv));
         }
diff --git a/libglusterfs/src/syncop.h b/libglusterfs/src/syncop.h
index a9cdee1fa00..c64b483e85c 100644
--- a/libglusterfs/src/syncop.h
+++ b/libglusterfs/src/syncop.h
@@ -231,7 +231,7 @@ struct syncopctx {
 	} while (0)
 
 
-#define SYNCOP(subvol, stb, cbk, op, params ...) do {                   \
+#define SYNCOP(subvol, stb, cbk, fn_op, params ...) do {                \
                 struct  synctask        *task = NULL;                   \
                 call_frame_t            *frame = NULL;                  \
                                                                         \
@@ -249,8 +249,9 @@ struct syncopctx {
                                                                         \
                 __yawn (stb);                                           \
                                                                         \
+                frame->op = get_fop_index_from_fn (subvol, fn_op);      \
                 STACK_WIND_COOKIE (frame, cbk, (void *)stb, subvol,     \
-                                   op, params);                         \
+                                   fn_op, params);                      \
                                                                         \
                 __yield (stb);                                          \
                 if (task)                                               \
diff --git a/libglusterfs/src/timespec.c b/libglusterfs/src/timespec.c
index 903303d1380..932a18c0103 100644
--- a/libglusterfs/src/timespec.c
+++ b/libglusterfs/src/timespec.c
@@ -12,6 +12,7 @@
 #include <inttypes.h>
 #include <time.h>
 #include <sys/time.h>
+#include <string.h>
 
 #if defined GF_DARWIN_HOST_OS
 #include <mach/mach_time.h>
@@ -21,17 +22,30 @@ static mach_timebase_info_data_t gf_timebase;
 #include "logging.h"
 #include "timespec.h"
 #include "libglusterfs-messages.h"
+#include "common-utils.h"
 
 void timespec_now (struct timespec *ts)
 {
 #if defined GF_LINUX_HOST_OS || defined GF_SOLARIS_HOST_OS || defined GF_BSD_HOST_OS
-        if (0 == clock_gettime(CLOCK_MONOTONIC, ts))
+        if (0 == clock_gettime(CLOCK_MONOTONIC, ts)) {
+                /* All good */
                 return;
-        else {
-                struct timeval tv;
-                if (0 == gettimeofday(&tv, NULL))
-                        TIMEVAL_TO_TIMESPEC(&tv, ts);
         }
+
+        /* Fall back, but there is hope in gettimeofday() syscall */
+        struct timeval tv;
+        if (0 == gettimeofday(&tv, NULL)) {
+                /* Again, all good */
+                TIMEVAL_TO_TIMESPEC(&tv, ts);
+                return;
+        }
+
+        /* If control hits here, there is surely a problem,
+           mainly because, as per man page too, these syscalls
+           shouldn't fail. Best way is to ABORT, because it is
+           not right */
+        GF_ABORT ("gettimeofday() failed!!");
+
 #elif defined GF_DARWIN_HOST_OS
         uint64_t time = mach_absolute_time();
         static double scaling = 0.0;
diff --git a/libglusterfs/src/xlator.h b/libglusterfs/src/xlator.h
index 26d2cc5b595..430dbadd517 100644
--- a/libglusterfs/src/xlator.h
+++ b/libglusterfs/src/xlator.h
@@ -727,13 +727,11 @@ typedef int32_t (*fop_setactivelk_t) (call_frame_t *frame, xlator_t *this,
                                       lock_migration_info_t *locklist,
                                       dict_t *xdata);
 
+/* WARNING: make sure the list is in order with FOP definition in
+   `rpc/xdr/src/glusterfs-fops.x`.
+   If it is not in order, mainly the metrics related feature would be broken */
 struct xlator_fops {
-        fop_lookup_t         lookup;
         fop_stat_t           stat;
-        fop_fstat_t          fstat;
-        fop_truncate_t       truncate;
-        fop_ftruncate_t      ftruncate;
-        fop_access_t         access;
         fop_readlink_t       readlink;
         fop_mknod_t          mknod;
         fop_mkdir_t          mkdir;
@@ -742,51 +740,59 @@ struct xlator_fops {
         fop_symlink_t        symlink;
         fop_rename_t         rename;
         fop_link_t           link;
-        fop_create_t         create;
+        fop_truncate_t       truncate;
         fop_open_t           open;
         fop_readv_t          readv;
         fop_writev_t         writev;
+        fop_statfs_t         statfs;
         fop_flush_t          flush;
         fop_fsync_t          fsync;
-        fop_opendir_t        opendir;
-        fop_readdir_t        readdir;
-        fop_readdirp_t       readdirp;
-        fop_fsyncdir_t       fsyncdir;
-        fop_statfs_t         statfs;
         fop_setxattr_t       setxattr;
         fop_getxattr_t       getxattr;
-        fop_fsetxattr_t      fsetxattr;
-        fop_fgetxattr_t      fgetxattr;
         fop_removexattr_t    removexattr;
-        fop_fremovexattr_t   fremovexattr;
+        fop_opendir_t        opendir;
+        fop_fsyncdir_t       fsyncdir;
+        fop_access_t         access;
+        fop_create_t         create;
+        fop_ftruncate_t      ftruncate;
+        fop_fstat_t          fstat;
         fop_lk_t             lk;
+        fop_lookup_t         lookup;
+        fop_readdir_t        readdir;
         fop_inodelk_t        inodelk;
         fop_finodelk_t       finodelk;
         fop_entrylk_t        entrylk;
         fop_fentrylk_t       fentrylk;
-        fop_rchecksum_t      rchecksum;
         fop_xattrop_t        xattrop;
         fop_fxattrop_t       fxattrop;
+        fop_fgetxattr_t      fgetxattr;
+        fop_fsetxattr_t      fsetxattr;
+        fop_rchecksum_t      rchecksum;
         fop_setattr_t        setattr;
         fop_fsetattr_t       fsetattr;
+        fop_readdirp_t       readdirp;
+
+        /* These 3 are required to keep the index same as GF_FOP_##FOP */
+        void *forget_placeholder;
+        void *release_placeholder;
+        void *releasedir_placeholder;
+
         fop_getspec_t        getspec;
-	fop_fallocate_t	     fallocate;
-	fop_discard_t	     discard;
+        fop_fremovexattr_t   fremovexattr;
+        fop_fallocate_t	     fallocate;
+        fop_discard_t	     discard;
         fop_zerofill_t       zerofill;
         fop_ipc_t            ipc;
         fop_seek_t           seek;
         fop_lease_t          lease;
         fop_compound_t       compound;
-        fop_getactivelk_t   getactivelk;
-        fop_setactivelk_t  setactivelk;
+        fop_getactivelk_t    getactivelk;
+        fop_setactivelk_t    setactivelk;
 
         /* these entries are used for a typechecking hack in STACK_WIND _only_ */
-        fop_lookup_cbk_t         lookup_cbk;
+        /* make sure to add _cbk variables only after defining regular fops as
+           its relative position is used to get the index */
         fop_stat_cbk_t           stat_cbk;
-        fop_fstat_cbk_t          fstat_cbk;
-        fop_truncate_cbk_t       truncate_cbk;
-        fop_ftruncate_cbk_t      ftruncate_cbk;
-        fop_access_cbk_t         access_cbk;
         fop_readlink_cbk_t       readlink_cbk;
         fop_mknod_cbk_t          mknod_cbk;
         fop_mkdir_cbk_t          mkdir_cbk;
@@ -795,43 +801,54 @@ struct xlator_fops {
         fop_symlink_cbk_t        symlink_cbk;
         fop_rename_cbk_t         rename_cbk;
         fop_link_cbk_t           link_cbk;
-        fop_create_cbk_t         create_cbk;
+        fop_truncate_cbk_t       truncate_cbk;
         fop_open_cbk_t           open_cbk;
         fop_readv_cbk_t          readv_cbk;
         fop_writev_cbk_t         writev_cbk;
+        fop_statfs_cbk_t         statfs_cbk;
         fop_flush_cbk_t          flush_cbk;
         fop_fsync_cbk_t          fsync_cbk;
-        fop_opendir_cbk_t        opendir_cbk;
-        fop_readdir_cbk_t        readdir_cbk;
-        fop_readdirp_cbk_t       readdirp_cbk;
-        fop_fsyncdir_cbk_t       fsyncdir_cbk;
-        fop_statfs_cbk_t         statfs_cbk;
         fop_setxattr_cbk_t       setxattr_cbk;
         fop_getxattr_cbk_t       getxattr_cbk;
-        fop_fsetxattr_cbk_t      fsetxattr_cbk;
-        fop_fgetxattr_cbk_t      fgetxattr_cbk;
         fop_removexattr_cbk_t    removexattr_cbk;
-        fop_fremovexattr_cbk_t   fremovexattr_cbk;
+        fop_opendir_cbk_t        opendir_cbk;
+        fop_fsyncdir_cbk_t       fsyncdir_cbk;
+        fop_access_cbk_t         access_cbk;
+        fop_create_cbk_t         create_cbk;
+        fop_ftruncate_cbk_t      ftruncate_cbk;
+        fop_fstat_cbk_t          fstat_cbk;
         fop_lk_cbk_t             lk_cbk;
+        fop_lookup_cbk_t         lookup_cbk;
+        fop_readdir_cbk_t        readdir_cbk;
         fop_inodelk_cbk_t        inodelk_cbk;
         fop_finodelk_cbk_t       finodelk_cbk;
         fop_entrylk_cbk_t        entrylk_cbk;
         fop_fentrylk_cbk_t       fentrylk_cbk;
-        fop_rchecksum_cbk_t      rchecksum_cbk;
         fop_xattrop_cbk_t        xattrop_cbk;
         fop_fxattrop_cbk_t       fxattrop_cbk;
+        fop_fgetxattr_cbk_t      fgetxattr_cbk;
+        fop_fsetxattr_cbk_t      fsetxattr_cbk;
+        fop_rchecksum_cbk_t      rchecksum_cbk;
         fop_setattr_cbk_t        setattr_cbk;
         fop_fsetattr_cbk_t       fsetattr_cbk;
+        fop_readdirp_cbk_t       readdirp_cbk;
+
+        /* These 3 are required to keep the index same as GF_FOP_##FOP */
+        void *forget_placeholder_cbk;
+        void *release_placeholder_cbk;
+        void *releasedir_placeholder_cbk;
+
         fop_getspec_cbk_t        getspec_cbk;
-	fop_fallocate_cbk_t	 fallocate_cbk;
-	fop_discard_cbk_t	 discard_cbk;
+        fop_fremovexattr_cbk_t   fremovexattr_cbk;
+        fop_fallocate_cbk_t      fallocate_cbk;
+        fop_discard_cbk_t        discard_cbk;
         fop_zerofill_cbk_t       zerofill_cbk;
         fop_ipc_cbk_t            ipc_cbk;
         fop_seek_cbk_t           seek_cbk;
         fop_lease_cbk_t          lease_cbk;
         fop_compound_cbk_t       compound_cbk;
-        fop_getactivelk_cbk_t   getactivelk_cbk;
-        fop_setactivelk_cbk_t  setactivelk_cbk;
+        fop_getactivelk_cbk_t    getactivelk_cbk;
+        fop_setactivelk_cbk_t    setactivelk_cbk;
 };
 
 typedef int32_t (*cbk_forget_t) (xlator_t *this,
@@ -906,7 +923,6 @@ typedef struct xlator_list {
         struct xlator_list *next;
 } xlator_list_t;
 
-
 struct _xlator {
         /* Built during parsing */
         char          *name;
@@ -933,9 +949,13 @@ struct _xlator {
 
         gf_loglevel_t    loglevel;   /* Log level for translator */
 
-        int64_t             client_latency;
-        /* for latency measurement */
-        fop_latency_t latencies[GF_FOP_MAXVALUE];
+        struct {
+                int64_t  client_latency; /* This is in 'milliseconds' units */
+                struct {
+                        /* for latency measurement */
+                        fop_latency_t latencies[GF_FOP_MAXVALUE];
+                } interval;
+        } stats;
 
         /* Misc */
         eh_t               *history; /* event history context */
diff --git a/rpc/rpc-lib/src/rpc-clnt-ping.c b/rpc/rpc-lib/src/rpc-clnt-ping.c
index 5a97f4bb9cf..2f11341b0d5 100644
--- a/rpc/rpc-lib/src/rpc-clnt-ping.c
+++ b/rpc/rpc-lib/src/rpc-clnt-ping.c
@@ -205,7 +205,8 @@ rpc_clnt_ping_cbk (struct rpc_req *req, struct iovec *iov, int count,
 
         pthread_mutex_lock (&conn->lock);
         {
-                this->client_latency = latency_msec;
+                /* TODO: concerned people, check why this is used nowhere? */
+                this->stats.client_latency = latency_msec;
                 gf_log (THIS->name, GF_LOG_DEBUG,
                         "Ping latency is %" PRIu64 "ms",
                         latency_msec);
diff --git a/xlators/debug/io-stats/src/io-stats.c b/xlators/debug/io-stats/src/io-stats.c
index 9c3ca2d0a69..b660e5ac8cb 100644
--- a/xlators/debug/io-stats/src/io-stats.c
+++ b/xlators/debug/io-stats/src/io-stats.c
@@ -223,7 +223,7 @@ is_fop_latency_started (call_frame_t *frame)
                                                                         \
                 conf = this->private;                                   \
                 if (conf && conf->measure_latency) {                    \
-                        gettimeofday (&frame->end, NULL);               \
+                        timespec_now (&frame->end);                     \
                         update_ios_latency (conf, frame, GF_FOP_##op);  \
                 }                                                       \
         } while (0)
@@ -234,7 +234,7 @@ is_fop_latency_started (call_frame_t *frame)
                                                                          \
                 conf = this->private;                                    \
                 if (conf && conf->measure_latency) {                     \
-                        gettimeofday (&frame->begin, NULL);              \
+                        timespec_now (&frame->begin);                    \
                 } else {                                                 \
                         memset (&frame->begin, 0, sizeof (frame->begin));\
                 }                                                        \
@@ -262,7 +262,7 @@ is_fop_latency_started (call_frame_t *frame)
                 if (conf && conf->measure_latency &&                          \
                     conf->count_fop_hits) {                                   \
                         BUMP_FOP (op);                                        \
-                        gettimeofday (&frame->end, NULL);                     \
+                        timespec_now (&frame->end);                           \
                         update_ios_latency (conf, frame, GF_FOP_##op);        \
                 }                                                             \
         } while (0)
@@ -271,15 +271,15 @@ is_fop_latency_started (call_frame_t *frame)
         do {                                                                   \
                 struct ios_conf         *conf = NULL;                          \
                 double                   elapsed;                              \
-                struct timeval          *begin, *end;                          \
+                struct timespec         *begin, *end;                          \
                 double                   throughput;                           \
                 int                      flag = 0;                             \
                                                                                \
                 begin = &frame->begin;                                         \
                 end   = &frame->end;                                           \
                                                                                \
-                elapsed = (end->tv_sec - begin->tv_sec) * 1e6                  \
-                        + (end->tv_usec - begin->tv_usec);                     \
+                elapsed = ((end->tv_sec - begin->tv_sec) * 1e9                 \
+                           + (end->tv_nsec - begin->tv_nsec)) / 1000;          \
                 throughput = op_ret / elapsed;                                 \
                                                                                \
                 conf = this->private;                                          \
@@ -1695,7 +1695,7 @@ void collect_ios_latency_sample (struct ios_conf *conf,
 {
         ios_sample_buf_t *ios_sample_buf = NULL;
         ios_sample_t     *ios_sample = NULL;
-        struct timeval   *timestamp = NULL;
+        struct timespec  *timestamp = NULL;
         call_stack_t     *root = NULL;
 
 
@@ -1714,7 +1714,7 @@ void collect_ios_latency_sample (struct ios_conf *conf,
         ios_sample->uid = root->uid;
         ios_sample->gid = root->gid;
         (ios_sample->timestamp).tv_sec = timestamp->tv_sec;
-        (ios_sample->timestamp).tv_usec = timestamp->tv_usec;
+        (ios_sample->timestamp).tv_usec = timestamp->tv_nsec / 1000;
         memcpy (&ios_sample->identifier, &root->identifier,
                 sizeof (root->identifier));
 
@@ -1759,13 +1759,13 @@ update_ios_latency (struct ios_conf *conf, call_frame_t *frame,
                     glusterfs_fop_t op)
 {
         double elapsed;
-        struct timeval *begin, *end;
+        struct timespec *begin, *end;
 
         begin = &frame->begin;
         end   = &frame->end;
 
-        elapsed = (end->tv_sec - begin->tv_sec) * 1e6
-                + (end->tv_usec - begin->tv_usec);
+        elapsed = ((end->tv_sec - begin->tv_sec) * 1e9
+                   + (end->tv_nsec - begin->tv_nsec)) / 1000;
 
         update_ios_latency_stats (&conf->cumulative, elapsed, op);
         update_ios_latency_stats (&conf->incremental, elapsed, op);
diff --git a/xlators/meta/src/frames-file.c b/xlators/meta/src/frames-file.c
index ebac3d9cbaa..027fa294fe8 100644
--- a/xlators/meta/src/frames-file.c
+++ b/xlators/meta/src/frames-file.c
@@ -48,9 +48,9 @@ frames_file_fill (xlator_t *this, inode_t *file, strfd_t *strfd)
                                                 frame->this->name);
                                 if (frame->begin.tv_sec)
                                         strprintf (strfd,
-                                                        "\t\t\t\"Creation_time\": %d.%d,\n",
-                                                        (int)frame->begin.tv_sec,
-                                                        (int)frame->begin.tv_usec);
+                                                   "\t\t\t\"Creation_time\": %d.%09d,\n",
+                                                   (int)frame->begin.tv_sec,
+                                                   (int)frame->begin.tv_nsec);
                                 strprintf (strfd, " \t\t\t\"Refcount\": %d,\n",
                                                 frame->ref_count);
                                 if (frame->parent)