rpcsvc: Add latency tracking for rpc programs

Added latency tracking of rpc-handling code. With this change we
should be able to monitor the amount of time rpc-handling code is
consuming for each of the rpc call.

fixes: #1466
Change-Id: I04fc7f3b12bfa5053c0fc36885f271cb78f581cd
Signed-off-by: Pranith Kumar K <pkarampu@redhat.com>

10 files changed, 115 insertions, 67 deletions

diff --git a/libglusterfs/src/glusterfs/latency.h b/libglusterfs/src/glusterfs/latency.h
index ed47b1f0cbc..4d601bbcbd6 100644
--- a/libglusterfs/src/glusterfs/latency.h
+++ b/libglusterfs/src/glusterfs/latency.h
@@ -11,13 +11,23 @@
 #ifndef __LATENCY_H__
 #define __LATENCY_H__
 
-#include "glusterfs/glusterfs.h"
+#include <inttypes.h>
+#include <time.h>
 
-typedef struct fop_latency {
-    double min;   /* min time for the call (microseconds) */
-    double max;   /* max time for the call (microseconds) */
-    double total; /* total time (microseconds) */
+typedef struct _gf_latency {
+    uint64_t min;   /* min time for the call (nanoseconds) */
+    uint64_t max;   /* max time for the call (nanoseconds) */
+    uint64_t total; /* total time (nanoseconds) */
     uint64_t count;
-} fop_latency_t;
+} gf_latency_t;
 
+gf_latency_t *
+gf_latency_new(size_t n);
+
+void
+gf_latency_reset(gf_latency_t *lat);
+
+void
+gf_latency_update(gf_latency_t *lat, struct timespec *begin,
+                  struct timespec *end);
 #endif /* __LATENCY_H__ */
diff --git a/libglusterfs/src/glusterfs/mem-types.h b/libglusterfs/src/glusterfs/mem-types.h
index 36cf7820ad5..d45d5b68c91 100644
--- a/libglusterfs/src/glusterfs/mem-types.h
+++ b/libglusterfs/src/glusterfs/mem-types.h
@@ -133,6 +133,7 @@ enum gf_common_mem_types_ {
     gf_common_volfile_t,
     gf_common_mt_mgmt_v3_lock_timer_t, /* used only in one location */
     gf_common_mt_server_cmdline_t,     /* used only in one location */
+    gf_common_mt_latency_t,
     gf_common_mt_end
 };
 #endif
diff --git a/libglusterfs/src/glusterfs/stack.h b/libglusterfs/src/glusterfs/stack.h
index bd466d8169e..536a330d38b 100644
--- a/libglusterfs/src/glusterfs/stack.h
+++ b/libglusterfs/src/glusterfs/stack.h
@@ -45,6 +45,9 @@ typedef int32_t (*ret_fn_t)(call_frame_t *frame, call_frame_t *prev_frame,
                             xlator_t *this, int32_t op_ret, int32_t op_errno,
                             ...);
 
+void
+gf_frame_latency_update(call_frame_t *frame);
+
 struct call_pool {
     union {
         struct list_head all_frames;
@@ -149,8 +152,6 @@ struct _call_stack {
     } while (0);
 
 struct xlator_fops;
-void
-gf_update_latency(call_frame_t *frame);
 
 static inline void
 FRAME_DESTROY(call_frame_t *frame)
@@ -158,7 +159,7 @@ FRAME_DESTROY(call_frame_t *frame)
     void *local = NULL;
 
     if (frame->root->ctx->measure_latency)
-        gf_update_latency(frame);
+        gf_frame_latency_update(frame);
 
     list_del_init(&frame->frames);
     if (frame->local) {
diff --git a/libglusterfs/src/glusterfs/statedump.h b/libglusterfs/src/glusterfs/statedump.h
index 89d04f94587..ce082706bdf 100644
--- a/libglusterfs/src/glusterfs/statedump.h
+++ b/libglusterfs/src/glusterfs/statedump.h
@@ -127,4 +127,6 @@ gf_proc_dump_xlator_meminfo(xlator_t *this, strfd_t *strfd);
 void
 gf_proc_dump_xlator_profile(xlator_t *this, strfd_t *strfd);
 
+void
+gf_latency_statedump_and_reset(char *key, gf_latency_t *lat);
 #endif /* STATEDUMP_H */
diff --git a/libglusterfs/src/glusterfs/xlator.h b/libglusterfs/src/glusterfs/xlator.h
index 23004ab2245..4fd3abdaeff 100644
--- a/libglusterfs/src/glusterfs/xlator.h
+++ b/libglusterfs/src/glusterfs/xlator.h
@@ -805,7 +805,7 @@ struct _xlator {
 
         struct {
             /* for latency measurement */
-            fop_latency_t latencies[GF_FOP_MAXVALUE];
+            gf_latency_t latencies[GF_FOP_MAXVALUE];
             /* for latency measurement */
             fop_metrics_t metrics[GF_FOP_MAXVALUE];
 
diff --git a/libglusterfs/src/latency.c b/libglusterfs/src/latency.c
index 8ec89093d41..ce4b0e8255d 100644
--- a/libglusterfs/src/latency.c
+++ b/libglusterfs/src/latency.c
@@ -16,34 +16,32 @@
 #include "glusterfs/glusterfs.h"
 #include "glusterfs/statedump.h"
 
-void
-gf_update_latency(call_frame_t *frame)
+gf_latency_t *
+gf_latency_new(size_t n)
 {
-    double elapsed;
-    struct timespec *begin, *end;
-
-    fop_latency_t *lat;
-
-    begin = &frame->begin;
-    end = &frame->end;
+    int i = 0;
+    gf_latency_t *lat = NULL;
 
-    if (!(begin->tv_sec && end->tv_sec))
-        goto out;
+    lat = GF_MALLOC(n * sizeof(*lat), gf_common_mt_latency_t);
+    if (!lat)
+        return NULL;
 
-    elapsed = gf_tsdiff(begin, end);
+    for (i = 0; i < n; i++) {
+        gf_latency_reset(lat + i);
+    }
+    return lat;
+}
 
-    if (frame->op < 0 || frame->op >= GF_FOP_MAXVALUE) {
-        gf_log("[core]", GF_LOG_WARNING, "Invalid frame op value: %d",
-               frame->op);
+void
+gf_latency_update(gf_latency_t *lat, struct timespec *begin,
+                  struct timespec *end)
+{
+    if (!(begin->tv_sec && end->tv_sec)) {
+        /*Measure latency might have been enabled/disabled during the op*/
         return;
     }
 
-    /* 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;
-
-    lat = &frame->this->stats.interval.latencies[frame->op];
+    double elapsed = gf_tsdiff(begin, end);
 
     if (lat->max < elapsed)
         lat->max = elapsed;
@@ -53,42 +51,34 @@ gf_update_latency(call_frame_t *frame)
 
     lat->total += elapsed;
     lat->count++;
-out:
-    return;
 }
 
 void
-gf_proc_dump_latency_info(xlator_t *xl)
+gf_latency_reset(gf_latency_t *lat)
 {
-    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("%s", key_prefix);
-
-    for (i = 0; i < GF_FOP_MAXVALUE; i++) {
-        gf_proc_dump_build_key(key, key_prefix, "%s", (char *)gf_fop_list[i]);
-
-        fop_latency_t *lat = &xl->stats.interval.latencies[i];
+    if (!lat)
+        return;
+    memset(lat, 0, sizeof(*lat));
+    lat->min = ULLONG_MAX;
+    /* make sure 'min' is set to high value, so it would be
+       properly set later */
+}
 
-        /* Doesn't make sense to continue if there are no fops
-           came in the given interval */
-        if (!lat->count)
-            continue;
+void
+gf_frame_latency_update(call_frame_t *frame)
+{
+    gf_latency_t *lat;
+    /* 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;
 
-        gf_proc_dump_write(
-            key, "AVG:%.03f,CNT:%" PRId64 ",TOTAL:%.03f,MIN:%.03f,MAX:%.03f",
-            (lat->total / lat->count), lat->count, lat->total, lat->min,
-            lat->max);
+    if (frame->op < 0 || frame->op >= GF_FOP_MAXVALUE) {
+        gf_log("[core]", GF_LOG_WARNING, "Invalid frame op value: %d",
+               frame->op);
+        return;
     }
 
-    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;
-    }
+    lat = &frame->this->stats.interval.latencies[frame->op];
+    gf_latency_update(lat, &frame->begin, &frame->end);
 }
diff --git a/libglusterfs/src/libglusterfs.sym b/libglusterfs/src/libglusterfs.sym
index 5213c2018d8..5f18cd56cbe 100644
--- a/libglusterfs/src/libglusterfs.sym
+++ b/libglusterfs/src/libglusterfs.sym
@@ -1186,3 +1186,8 @@ gf_nanosleep
 gf_syncfs
 graph_total_client_xlator
 get_xattrs_to_heal
+gf_latency_statedump_and_reset
+gf_latency_new
+gf_latency_reset
+gf_latency_update
+gf_frame_latency_update
diff --git a/libglusterfs/src/monitoring.c b/libglusterfs/src/monitoring.c
index 45e3d776903..fbb68dc8622 100644
--- a/libglusterfs/src/monitoring.c
+++ b/libglusterfs/src/monitoring.c
@@ -113,15 +113,15 @@ dump_latency_and_count(xlator_t *xl, int fd)
             dprintf(fd, "%s.interval.%s.fail_count %" PRIu64 "\n", xl->name,
                     gf_fop_list[index], cbk);
         }
-        if (xl->stats.interval.latencies[index].count != 0.0) {
+        if (xl->stats.interval.latencies[index].count != 0) {
             dprintf(fd, "%s.interval.%s.latency %lf\n", xl->name,
                     gf_fop_list[index],
-                    (xl->stats.interval.latencies[index].total /
+                    (((double)xl->stats.interval.latencies[index].total) /
                      xl->stats.interval.latencies[index].count));
-            dprintf(fd, "%s.interval.%s.max %lf\n", xl->name,
+            dprintf(fd, "%s.interval.%s.max %" PRIu64 "\n", xl->name,
                     gf_fop_list[index],
                     xl->stats.interval.latencies[index].max);
-            dprintf(fd, "%s.interval.%s.min %lf\n", xl->name,
+            dprintf(fd, "%s.interval.%s.min %" PRIu64 "\n", xl->name,
                     gf_fop_list[index],
                     xl->stats.interval.latencies[index].min);
         }
diff --git a/libglusterfs/src/statedump.c b/libglusterfs/src/statedump.c
index c1aa9b69aa2..65f0eb5c7f3 100644
--- a/libglusterfs/src/statedump.c
+++ b/libglusterfs/src/statedump.c
@@ -199,6 +199,40 @@ gf_proc_dump_write(char *key, char *value, ...)
     return ret;
 }
 
+void
+gf_latency_statedump_and_reset(char *key, gf_latency_t *lat)
+{
+    /* Doesn't make sense to continue if there are no fops
+       came in the given interval */
+    if (!lat || !lat->count)
+        return;
+    gf_proc_dump_write(key,
+                       "AVG:%lf CNT:%" PRIu64 " TOTAL:%" PRIu64 " MIN:%" PRIu64
+                       " MAX:%" PRIu64,
+                       (((double)lat->total) / lat->count), lat->count,
+                       lat->total, lat->min, lat->max);
+    gf_latency_reset(lat);
+}
+
+void
+gf_proc_dump_xl_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("%s", key_prefix);
+
+    for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+        gf_proc_dump_build_key(key, key_prefix, "%s", (char *)gf_fop_list[i]);
+
+        gf_latency_t *lat = &xl->stats.interval.latencies[i];
+
+        gf_latency_statedump_and_reset(key, lat);
+    }
+}
+
 static void
 gf_proc_dump_xlator_mem_info(xlator_t *xl)
 {
@@ -467,7 +501,7 @@ gf_proc_dump_single_xlator_info(xlator_t *trav)
         return;
 
     if (ctx->measure_latency)
-        gf_proc_dump_latency_info(trav);
+        gf_proc_dump_xl_latency_info(trav);
 
     gf_proc_dump_xlator_mem_info(trav);
 
@@ -1011,7 +1045,7 @@ gf_proc_dump_xlator_profile(xlator_t *this, strfd_t *strfd)
     {
         gf_dump_strfd = strfd;
 
-        gf_proc_dump_latency_info(this);
+        gf_proc_dump_xl_latency_info(this);
 
         gf_dump_strfd = NULL;
     }
diff --git a/libglusterfs/src/xlator.c b/libglusterfs/src/xlator.c
index a54aadd76c7..9a2582d45d5 100644
--- a/libglusterfs/src/xlator.c
+++ b/libglusterfs/src/xlator.c
@@ -260,6 +260,7 @@ xlator_dynload_apis(xlator_t *xl)
     void *handle = NULL;
     volume_opt_list_t *vol_opt = NULL;
     xlator_api_t *xlapi = NULL;
+    int i = 0;
 
     handle = xl->dlhandle;
 
@@ -357,6 +358,10 @@ xlator_dynload_apis(xlator_t *xl)
     memcpy(xl->op_version, xlapi->op_version,
            sizeof(uint32_t) * GF_MAX_RELEASES);
 
+    for (i = 0; i < GF_FOP_MAXVALUE; i++) {
+        gf_latency_reset(&xl->stats.interval.latencies[i]);
+    }
+
     ret = 0;
 out:
     return ret;