core: Do internal latency measurement of FOPs.

This patch adds a facility by which each translator
keeps track of the average latency of a FOP from
its point of view. That is, the duration between
the translator handing over the call to a lower-level
translator and the reply coming back.

The latency measurement is off by default, and can
be toggled by sending SIGUSR2 to the GlusterFS process.

Latency data is printed as part of the process state dump.

Signed-off-by: Vikas Gorur <vikas@gluster.com>
Signed-off-by: Anand V. Avati <avati@dev.gluster.com>

BUG: 268 (Add timing instrumentation code)
URL: http://bugs.gluster.com/cgi-bin/bugzilla3/show_bug.cgi?id=268

7 files changed, 292 insertions, 4 deletions

diff --git a/libglusterfs/src/Makefile.am b/libglusterfs/src/Makefile.am
index 755c2d807..82c634dea 100644
--- a/libglusterfs/src/Makefile.am
+++ b/libglusterfs/src/Makefile.am
@@ -6,9 +6,9 @@ libglusterfs_la_LIBADD = @LEXLIB@
 
 lib_LTLIBRARIES = libglusterfs.la
 
-libglusterfs_la_SOURCES = dict.c spec.lex.c y.tab.c xlator.c logging.c  hashfn.c defaults.c scheduler.c common-utils.c transport.c timer.c inode.c call-stub.c compat.c authenticate.c fd.c compat-errno.c event.c mem-pool.c gf-dirent.c syscall.c iobuf.c globals.c statedump.c stack.c checksum.c md5.c $(CONTRIBDIR)/rbtree/rb.c rbthash.c
+libglusterfs_la_SOURCES = dict.c spec.lex.c y.tab.c xlator.c logging.c  hashfn.c defaults.c scheduler.c common-utils.c transport.c timer.c inode.c call-stub.c compat.c authenticate.c fd.c compat-errno.c event.c mem-pool.c gf-dirent.c syscall.c iobuf.c globals.c statedump.c stack.c checksum.c md5.c $(CONTRIBDIR)/rbtree/rb.c rbthash.c latency.c
 
-noinst_HEADERS = common-utils.h defaults.h dict.h glusterfs.h hashfn.h logging.h protocol.h scheduler.h xlator.h transport.h stack.h timer.h list.h inode.h call-stub.h compat.h authenticate.h fd.h revision.h compat-errno.h event.h mem-pool.h byte-order.h gf-dirent.h locking.h syscall.h iobuf.h globals.h statedump.h checksum.h md5.h $(CONTRIBDIR)/rbtree/rb.h rbthash.h iatt.h
+noinst_HEADERS = common-utils.h defaults.h dict.h glusterfs.h hashfn.h logging.h protocol.h scheduler.h xlator.h transport.h stack.h timer.h list.h inode.h call-stub.h compat.h authenticate.h fd.h revision.h compat-errno.h event.h mem-pool.h byte-order.h gf-dirent.h locking.h syscall.h iobuf.h globals.h statedump.h checksum.h md5.h $(CONTRIBDIR)/rbtree/rb.h rbthash.h iatt.h latency.h
 
 EXTRA_DIST = spec.l spec.y
 
diff --git a/libglusterfs/src/glusterfs.h b/libglusterfs/src/glusterfs.h
index 4abde409b..cf87af7d3 100644
--- a/libglusterfs/src/glusterfs.h
+++ b/libglusterfs/src/glusterfs.h
@@ -260,6 +260,7 @@ struct _glusterfs_ctx {
 	int                xl_count;
         uint32_t           volfile_checksum;
         size_t             page_size;
+        unsigned char      measure_latency; /* toggle switch for latency measurement */
 };
 
 typedef struct _glusterfs_ctx glusterfs_ctx_t;
diff --git a/libglusterfs/src/latency.c b/libglusterfs/src/latency.c
new file mode 100644
index 000000000..bccc780a2
--- /dev/null
+++ b/libglusterfs/src/latency.c
@@ -0,0 +1,191 @@
+/*
+  Copyright (c) 2009 Gluster, Inc. <http://www.gluster.com>
+  This file is part of GlusterFS.
+
+  GlusterFS is free software; you can redistribute it and/or modify
+  it under the terms of the GNU General Public License as published
+  by the Free Software Foundation; either version 3 of the License,
+  or (at your option) any later version.
+
+  GlusterFS is distributed in the hope that it will be useful, but
+  WITHOUT ANY WARRANTY; without even the implied warranty of
+  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+  General Public License for more details.
+
+  You should have received a copy of the GNU General Public License
+  along with this program.  If not, see
+  <http://www.gnu.org/licenses/>.
+*/
+
+
+/*
+ * This file contains functions to support dumping of
+ * latencies of FOPs broken down by subvolumes.
+ */
+
+#include "glusterfs.h"
+#include "stack.h"
+#include "xlator.h"
+#include "common-utils.h"
+#include "statedump.h"
+
+
+void
+gf_set_fop_from_fn_pointer (call_frame_t *frame, struct xlator_fops *fops,
+                            struct xlator_mops *mops, void *fn)
+{
+        glusterfs_fop_t fop = -1;
+
+        if (fops->stat == fn)
+                fop = GF_FOP_STAT;
+        else if (fops->readlink == fn)
+                fop = GF_FOP_READLINK;
+        else if (fops->mknod == fn)
+                fop = GF_FOP_MKNOD;
+        else if (fops->mkdir == fn)
+                fop = GF_FOP_MKDIR;
+        else if (fops->unlink == fn)
+                fop = GF_FOP_UNLINK;
+        else if (fops->rmdir == fn)
+                fop = GF_FOP_RMDIR;
+        else if (fops->symlink == fn)
+                fop = GF_FOP_SYMLINK;
+        else if (fops->rename == fn)
+                fop = GF_FOP_RENAME;
+        else if (fops->link == fn)
+                fop = GF_FOP_LINK;
+        else if (fops->truncate == fn)
+                fop = GF_FOP_TRUNCATE;
+        else if (fops->open == fn)
+                fop = GF_FOP_OPEN;
+        else if (fops->readv == fn)
+                fop = GF_FOP_READ;
+        else if (fops->writev == fn)
+                fop = GF_FOP_WRITE;
+        else if (fops->statfs == fn)
+                fop = GF_FOP_STATFS;
+        else if (fops->flush == fn)
+                fop = GF_FOP_FLUSH;
+        else if (fops->fsync == fn)
+                fop = GF_FOP_FSYNC;
+        else if (fops->setxattr == fn)
+                fop = GF_FOP_SETXATTR;
+        else if (fops->getxattr == fn)
+                fop = GF_FOP_GETXATTR;
+        else if (fops->removexattr == fn)
+                fop = GF_FOP_REMOVEXATTR;
+        else if (fops->opendir == fn)
+                fop = GF_FOP_OPENDIR;
+        else if (fops->fsyncdir == fn)
+                fop = GF_FOP_FSYNCDIR;
+        else if (fops->access == fn)
+                fop = GF_FOP_ACCESS;
+        else if (fops->create == fn)
+                fop = GF_FOP_CREATE;
+        else if (fops->ftruncate == fn)
+                fop = GF_FOP_FTRUNCATE;
+        else if (fops->fstat == fn)
+                fop = GF_FOP_FSTAT;
+        else if (fops->lk == fn)
+                fop = GF_FOP_LK;
+        else if (fops->lookup == fn)
+                fop = GF_FOP_LOOKUP;
+        else if (fops->readdir == fn)
+                fop = GF_FOP_READDIR;
+        else if (fops->inodelk == fn)
+                fop = GF_FOP_INODELK;
+        else if (fops->finodelk == fn)
+                fop = GF_FOP_FINODELK;
+	else if (fops->entrylk == fn)
+                fop = GF_FOP_ENTRYLK;
+	else if (fops->fentrylk == fn)
+                fop = GF_FOP_FENTRYLK;
+        else if (fops->checksum == fn)
+                fop = GF_FOP_CHECKSUM;
+        else if (fops->xattrop == fn)
+                fop = GF_FOP_XATTROP;
+        else if (fops->fxattrop == fn)
+                fop = GF_FOP_FXATTROP;
+        else if (fops->fgetxattr == fn)
+                fop = GF_FOP_FGETXATTR;
+        else if (fops->fsetxattr == fn)
+                fop = GF_FOP_FSETXATTR;
+        else if (fops->rchecksum == fn)
+                fop = GF_FOP_RCHECKSUM;
+        else if (fops->setattr == fn)
+                fop = GF_FOP_SETATTR;
+        else if (fops->fsetattr == fn)
+                fop = GF_FOP_FSETATTR;
+        else if (fops->readdirp == fn)
+                fop = GF_FOP_READDIRP;
+        else {
+                if (mops->getspec == fn)
+                        fop = GF_MOP_GETSPEC;
+                else if (mops->log == fn)
+                        fop = GF_MOP_LOG;
+                else {
+                        fop = -1;
+                }
+        }
+
+        frame->op   = fop;
+}
+
+
+void
+gf_update_latency (call_frame_t *frame)
+{
+        double elapsed;
+        struct timeval *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];
+
+	lat->total += elapsed;
+        lat->count++;
+        lat->mean = lat->mean + (elapsed - lat->mean) / lat->count;
+}
+
+
+void
+gf_proc_dump_latency_info (xlator_t *xl)
+{
+        char key_prefix[GF_DUMP_MAX_BUF_LEN];
+        char key[GF_DUMP_MAX_BUF_LEN];
+        int i;
+
+        snprintf (key_prefix, GF_DUMP_MAX_BUF_LEN, "%s.latency", xl->name);
+        gf_proc_dump_add_section (key_prefix);
+
+        for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+                gf_proc_dump_build_key (key, key_prefix, gf_fop_list[i]);
+
+                gf_proc_dump_write (key, "%.03f,%"PRId64",%.03f",
+                                    xl->latencies[i].mean,
+                                    xl->latencies[i].count,
+				    xl->latencies[i].total);
+        }
+}
+
+
+void
+gf_latency_toggle (int signum)
+{
+        glusterfs_ctx_t *ctx = NULL;
+
+        ctx = get_global_ctx_ptr ();
+
+        if (ctx) {
+                ctx->measure_latency = !ctx->measure_latency;
+                gf_log ("[core]", GF_LOG_NORMAL,
+                        "Latency measurement turned %s",
+                        ctx->measure_latency ? "on" : "off");
+        }
+}
diff --git a/libglusterfs/src/latency.h b/libglusterfs/src/latency.h
new file mode 100644
index 000000000..ba7d76cdd
--- /dev/null
+++ b/libglusterfs/src/latency.h
@@ -0,0 +1,36 @@
+/*
+  Copyright (c) 2009 Gluster, Inc. <http://www.gluster.com>
+  This file is part of GlusterFS.
+
+  GlusterFS is free software; you can redistribute it and/or modify
+  it under the terms of the GNU General Public License as published
+  by the Free Software Foundation; either version 3 of the License,
+  or (at your option) any later version.
+
+  GlusterFS is distributed in the hope that it will be useful, but
+  WITHOUT ANY WARRANTY; without even the implied warranty of
+  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+  General Public License for more details.
+
+  You should have received a copy of the GNU General Public License
+  along with this program.  If not, see
+  <http://www.gnu.org/licenses/>.
+*/
+
+#ifndef __LATENCY_H__
+#define __LATENCY_H__
+
+
+typedef struct fop_latency {
+        uint64_t min;           /* min time for the call (microseconds) */
+        uint64_t 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;
+
+void
+gf_latency_toggle (int signum);
+
+#endif /* __LATENCY_H__ */
diff --git a/libglusterfs/src/stack.h b/libglusterfs/src/stack.h
index cc059f068..25925f7a6 100644
--- a/libglusterfs/src/stack.h
+++ b/libglusterfs/src/stack.h
@@ -37,6 +37,8 @@ typedef struct _call_frame_t call_frame_t;
 struct _call_pool_t;
 typedef struct _call_pool_t call_pool_t;
 
+#include <sys/time.h>
+
 #include "xlator.h"
 #include "dict.h"
 #include "list.h"
@@ -76,6 +78,10 @@ struct _call_frame_t {
 	gf_lock_t     lock;
 	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 */
 };
 
 struct _call_stack_t {
@@ -113,6 +119,16 @@ struct _call_stack_t {
                 }                                                       \
         } while (0);                                                    \
 
+struct xlator_fops;
+struct xlator_mops;
+
+void
+gf_set_fop_from_fn_pointer (call_frame_t *frame, struct xlator_fops *fops,
+                            struct xlator_mops *mops, void *fn);
+
+void
+gf_update_latency (call_frame_t *frame);
+
 static inline void
 FRAME_DESTROY (call_frame_t *frame)
 {
@@ -130,6 +146,13 @@ FRAME_DESTROY (call_frame_t *frame)
 static inline void
 STACK_DESTROY (call_stack_t *stack)
 {
+        glusterfs_ctx_t *ctx = get_global_ctx_ptr ();
+
+        if (ctx && ctx->measure_latency) {
+                gettimeofday (&stack->frames.end, NULL);
+                gf_update_latency (&stack->frames);
+        }
+
 	LOCK (&stack->pool->lock);
 	{
 		list_del_init (&stack->all_frames);
@@ -143,6 +166,10 @@ STACK_DESTROY (call_stack_t *stack)
 	LOCK_DESTROY (&stack->frames.lock);
 
 	while (stack->frames.next) {
+                if (ctx && ctx->measure_latency) {
+                        gf_update_latency (stack->frames.next);
+                }
+
 		FRAME_DESTROY (stack->frames.next);
 	}
 	FREE (stack);
@@ -173,7 +200,12 @@ STACK_DESTROY (call_stack_t *stack)
 		_new->cookie = _new;					\
 		LOCK_INIT (&_new->lock);				\
 		frame->ref_count++;					\
-									\
+                                                                        \
+                if (((xlator_t *) obj)->ctx->measure_latency) {         \
+                        gettimeofday (&_new->begin, NULL);              \
+                        gf_set_fop_from_fn_pointer (_new, ((xlator_t *)obj)->fops, ((xlator_t *)obj)->mops, fn); \
+                }                                                       \
+                                                                        \
                 old_THIS = THIS;                                        \
                 THIS = obj;                                             \
 		fn (_new, obj, params);					\
@@ -203,7 +235,12 @@ STACK_DESTROY (call_stack_t *stack)
 		LOCK_INIT (&_new->lock);				\
 		frame->ref_count++;					\
 		fn##_cbk = rfn;						\
-									\
+                                                                        \
+                if (((xlator_t *) obj)->ctx->measure_latency) {         \
+                        gettimeofday (&_new->begin, NULL);              \
+                        gf_set_fop_from_fn_pointer (_new, ((xlator_t *)obj)->fops, ((xlator_t *)obj)->mops, fn); \
+                }                                                       \
+                                                                        \
                 old_THIS = THIS;                                        \
                 THIS = obj;                                             \
 		fn (_new, obj, params);					\
@@ -224,6 +261,11 @@ STACK_DESTROY (call_stack_t *stack)
                 old_THIS = THIS;                                        \
                 THIS = _parent->this;                                   \
                 frame->complete = _gf_true;                             \
+                                                                        \
+                if (((xlator_t *) old_THIS)->ctx->measure_latency) {	\
+			gettimeofday (&frame->end, NULL);		\
+                }                                                       \
+                                                                        \
 		fn (_parent, frame->cookie, _parent->this, params);	\
                 THIS = old_THIS;                                        \
 	} while (0)
@@ -242,6 +284,11 @@ STACK_DESTROY (call_stack_t *stack)
                 old_THIS = THIS;                                        \
                 THIS = _parent->this;                                   \
                 frame->complete = _gf_true;                             \
+                                                                        \
+                if (((xlator_t *) old_THIS)->ctx->measure_latency) {	\
+                        gettimeofday (&frame->end, NULL);               \
+                }                                                       \
+                                                                        \
 		fn (_parent, frame->cookie, _parent->this, params);	\
                 THIS = old_THIS;                                        \
 	} while (0)
@@ -294,6 +341,7 @@ static inline call_frame_t *
 create_frame (xlator_t *xl, call_pool_t *pool)
 {
 	call_stack_t *stack = NULL;
+        glusterfs_ctx_t *ctx = get_global_ctx_ptr ();
 
 	if (!xl || !pool) {
 		return NULL;
@@ -316,6 +364,10 @@ create_frame (xlator_t *xl, call_pool_t *pool)
 
 	LOCK_INIT (&stack->frames.lock);
 
+        if (ctx && ctx->measure_latency) {
+                gettimeofday (&stack->frames.begin, NULL);
+        }
+
 	return &stack->frames;
 }
 
diff --git a/libglusterfs/src/statedump.c b/libglusterfs/src/statedump.c
index 7f1e3e241..4e4228006 100644
--- a/libglusterfs/src/statedump.c
+++ b/libglusterfs/src/statedump.c
@@ -141,6 +141,7 @@ gf_proc_dump_mem_info ()
 
 }
 
+void gf_proc_dump_latency_info (xlator_t *xl);
 
 void
 gf_proc_dump_xlator_info (xlator_t *this_xl)
@@ -150,6 +151,8 @@ gf_proc_dump_xlator_info (xlator_t *this_xl)
                 return;
 
         while (this_xl) {
+                gf_proc_dump_latency_info (this_xl);
+
                 if (!this_xl->dumpops) {
                         this_xl = this_xl->next;
                         continue;
@@ -160,6 +163,7 @@ gf_proc_dump_xlator_info (xlator_t *this_xl)
                         this_xl->dumpops->inode(this_xl);
                 if (this_xl->dumpops->fd)
                         this_xl->dumpops->fd(this_xl);
+
                 this_xl = this_xl->next;
         }
 
diff --git a/libglusterfs/src/xlator.h b/libglusterfs/src/xlator.h
index 8cde2ed31..993679b25 100644
--- a/libglusterfs/src/xlator.h
+++ b/libglusterfs/src/xlator.h
@@ -36,6 +36,7 @@
 #include "dict.h"
 #include "compat.h"
 #include "list.h"
+#include "latency.h"
 
 #define FIRST_CHILD(xl) (xl->children->xlator)
 
@@ -847,6 +848,9 @@ struct _xlator {
 	int32_t           (*init) (xlator_t *this);
 	event_notify_fn_t notify;
 
+        /* for latency measurement */
+        fop_latency_t latencies[GF_FOP_MAXVALUE];
+
 	/* Misc */
 	glusterfs_ctx_t  *ctx;
 	inode_table_t    *itable;