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>

1 files changed, 41 insertions, 51 deletions

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);
 }