From f2b9d3a089cc9ff9910da0075defe306851aca5c Mon Sep 17 00:00:00 2001

From: Ravishankar N <ravishankar@redhat.com>

Date: Fri, 4 Jun 2021 12:27:57 +0530

Subject: [PATCH 576/584] 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.

Upstream patch details:

> https://review.gluster.org/#/c/glusterfs/+/24955/

> fixes: #1466

> Change-Id: I04fc7f3b12bfa5053c0fc36885f271cb78f581cd

> Signed-off-by: Pranith Kumar K <pkarampu@redhat.com>

BUG: 1928676

Change-Id: Ibcedddb5db3ff4906607050cf9f7ea3ebb266cc5

Signed-off-by: Ravishankar N <ravishankar@redhat.com>

Reviewed-on: https://code.engineering.redhat.com/gerrit/c/rhs-glusterfs/+/245295

Tested-by: RHGS Build Bot <nigelb@redhat.com>

Reviewed-by: Xavi Hernandez Juan <xhernandez@redhat.com>

Reviewed-by: Ashish Pandey <aspandey@redhat.com>

Reviewed-by: Sunil Kumar Heggodu Gopala Acharya <sheggodu@redhat.com>

---

 libglusterfs/src/glusterfs/latency.h   | 22 +++++---

 libglusterfs/src/glusterfs/mem-types.h |  1 +

 libglusterfs/src/glusterfs/stack.h     |  7 +--

 libglusterfs/src/glusterfs/statedump.h |  2 +

 libglusterfs/src/glusterfs/xlator.h    |  2 +-

 libglusterfs/src/latency.c             | 93 +++++++++++++++-------------------

 libglusterfs/src/libglusterfs.sym      |  5 ++

 libglusterfs/src/monitoring.c          |  8 +--

 libglusterfs/src/statedump.c           | 38 +++++++++++++-

 libglusterfs/src/xlator.c              |  5 ++

 rpc/rpc-lib/src/libgfrpc.sym           |  1 +

 rpc/rpc-lib/src/rpcsvc.c               | 72 +++++++++++++++++++++++++-

 rpc/rpc-lib/src/rpcsvc.h               |  5 ++

 xlators/protocol/server/src/server.c   |  2 +

 14 files changed, 193 insertions(+), 70 deletions(-)

diff --git a/libglusterfs/src/glusterfs/latency.h b/libglusterfs/src/glusterfs/latency.h

index ed47b1f..4d601bb 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 92730a9..970b9ff 100644

--- a/libglusterfs/src/glusterfs/mem-types.h

+++ b/libglusterfs/src/glusterfs/mem-types.h

@@ -139,6 +139,7 @@ enum gf_common_mem_types_ {

     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_mt_gfdb_query_record_t,

+    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 bd466d8..536a330 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 89d04f9..ce08270 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 273039a..ecb9fa4 100644

--- a/libglusterfs/src/glusterfs/xlator.h

+++ b/libglusterfs/src/glusterfs/xlator.h

@@ -808,7 +808,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 ce61399..ce4b0e8 100644

--- a/libglusterfs/src/latency.c

+++ b/libglusterfs/src/latency.c

@@ -14,39 +14,34 @@

  */

 #include "glusterfs/glusterfs.h"

-#include "glusterfs/xlator.h"

-#include "glusterfs/common-utils.h"

 #include "glusterfs/statedump.h"

-#include "glusterfs/libglusterfs-messages.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;

@@ -56,40 +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, "%.03f,%" PRId64 ",%.03f",

-                           (lat->total / lat->count), lat->count, lat->total);

+    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 9072afa..4f968e1 100644

--- a/libglusterfs/src/libglusterfs.sym

+++ b/libglusterfs/src/libglusterfs.sym

@@ -1183,3 +1183,8 @@ gf_latency_reset

 gf_latency_update

 gf_frame_latency_update

 gf_assert

+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 6d9bfb1..20b7f52 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 d18b50f..4bf4cc2 100644

--- a/libglusterfs/src/statedump.c

+++ b/libglusterfs/src/statedump.c

@@ -201,6 +201,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)

 {

@@ -487,7 +521,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);

@@ -1024,7 +1058,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 36cc32c..b9ad411 100644

--- a/libglusterfs/src/xlator.c

+++ b/libglusterfs/src/xlator.c

@@ -246,6 +246,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;

@@ -343,6 +344,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;

diff --git a/rpc/rpc-lib/src/libgfrpc.sym b/rpc/rpc-lib/src/libgfrpc.sym

index f3544e3..a1757cc 100644

--- a/rpc/rpc-lib/src/libgfrpc.sym

+++ b/rpc/rpc-lib/src/libgfrpc.sym

@@ -66,3 +66,4 @@ rpc_transport_unix_options_build

 rpc_transport_unref

 rpc_clnt_mgmt_pmap_signout

 rpcsvc_autoscale_threads

+rpcsvc_statedump

diff --git a/rpc/rpc-lib/src/rpcsvc.c b/rpc/rpc-lib/src/rpcsvc.c

index b031d93..855b512 100644

--- a/rpc/rpc-lib/src/rpcsvc.c

+++ b/rpc/rpc-lib/src/rpcsvc.c

@@ -25,6 +25,7 @@

 #include <glusterfs/syncop.h>

 #include "rpc-drc.h"

 #include "protocol-common.h"

+#include <glusterfs/statedump.h>

 #include <errno.h>

 #include <pthread.h>

@@ -377,6 +378,10 @@ rpcsvc_program_actor(rpcsvc_request_t *req)

         goto err;

     }

+    if (svc->xl->ctx->measure_latency) {

+        timespec_now(&req->begin);

+    }

+

     req->ownthread = program->ownthread;

     req->synctask = program->synctask;

@@ -1526,10 +1531,18 @@ rpcsvc_submit_generic(rpcsvc_request_t *req, struct iovec *proghdr,

     size_t hdrlen = 0;

     char new_iobref = 0;

     rpcsvc_drc_globals_t *drc = NULL;

+    gf_latency_t *lat = NULL;

     if ((!req) || (!req->trans))

         return -1;

+    if (req->prog && req->begin.tv_sec) {

+        if ((req->procnum >= 0) && (req->procnum < req->prog->numactors)) {

+            timespec_now(&req->end);

+            lat = &req->prog->latencies[req->procnum];

+            gf_latency_update(lat, &req->begin, &req->end);

+        }

+    }

     trans = req->trans;

     for (i = 0; i < hdrcount; i++) {

@@ -1860,6 +1873,15 @@ rpcsvc_submit_message(rpcsvc_request_t *req, struct iovec *proghdr,

                                  iobref);

 }

+void

+rpcsvc_program_destroy(rpcsvc_program_t *program)

+{

+    if (program) {

+        GF_FREE(program->latencies);

+        GF_FREE(program);

+    }

+}

+

 int

 rpcsvc_program_unregister(rpcsvc_t *svc, rpcsvc_program_t *program)

 {

@@ -1917,8 +1939,7 @@ rpcsvc_program_unregister(rpcsvc_t *svc, rpcsvc_program_t *program)

     ret = 0;

 out:

-    if (prog)

-        GF_FREE(prog);

+    rpcsvc_program_destroy(prog);

     if (ret == -1) {

         if (program) {

@@ -2303,6 +2324,11 @@ rpcsvc_program_register(rpcsvc_t *svc, rpcsvc_program_t *program,

     }

     memcpy(newprog, program, sizeof(*program));

+    newprog->latencies = gf_latency_new(program->numactors);

+    if (!newprog->latencies) {

+        rpcsvc_program_destroy(newprog);

+        goto out;

+    }

     INIT_LIST_HEAD(&newprog->program);

     pthread_mutexattr_init(&thr_attr);

@@ -3240,6 +3266,48 @@ out:

     return ret;

 }

+void

+rpcsvc_program_dump(rpcsvc_program_t *prog)

+{

+    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", prog->progname);

+    gf_proc_dump_add_section("%s", key_prefix);

+

+    gf_proc_dump_build_key(key, key_prefix, "program-number");

+    gf_proc_dump_write(key, "%d", prog->prognum);

+

+    gf_proc_dump_build_key(key, key_prefix, "program-version");

+    gf_proc_dump_write(key, "%d", prog->progver);

+

+    strncat(key_prefix, ".latency",

+            sizeof(key_prefix) - strlen(key_prefix) - 1);

+

+    for (i = 0; i < prog->numactors; i++) {

+        gf_proc_dump_build_key(key, key_prefix, "%s", prog->actors[i].procname);

+        gf_latency_statedump_and_reset(key, &prog->latencies[i]);

+    }

+}

+

+void

+rpcsvc_statedump(rpcsvc_t *svc)

+{

+    rpcsvc_program_t *prog = NULL;

+    int ret = 0;

+    ret = pthread_rwlock_tryrdlock(&svc->rpclock);

+    if (ret)

+        return;

+    {

+        list_for_each_entry(prog, &svc->programs, program)

+        {

+            rpcsvc_program_dump(prog);

+        }

+    }

+    pthread_rwlock_unlock(&svc->rpclock);

+}

+

 rpcsvc_actor_t gluster_dump_actors[GF_DUMP_MAXVALUE] = {

     [GF_DUMP_NULL] = {"NULL", GF_DUMP_NULL, NULL, NULL, 0, DRC_NA},

     [GF_DUMP_DUMP] = {"DUMP", GF_DUMP_DUMP, rpcsvc_dump, NULL, 0, DRC_NA},

diff --git a/rpc/rpc-lib/src/rpcsvc.h b/rpc/rpc-lib/src/rpcsvc.h

index a51edc7..e336d00 100644

--- a/rpc/rpc-lib/src/rpcsvc.h

+++ b/rpc/rpc-lib/src/rpcsvc.h

@@ -275,6 +275,8 @@ struct rpcsvc_request {

     gf_boolean_t ownthread;

     gf_boolean_t synctask;

+    struct timespec begin; /*req handling start time*/

+    struct timespec end;   /*req handling end time*/

 };

 #define rpcsvc_request_program(req) ((rpcsvc_program_t *)((req)->prog))

@@ -431,6 +433,7 @@ struct rpcsvc_program {

     /* Program specific state handed to actors */

     void *private;

+    gf_latency_t *latencies; /*Tracks latency statistics for the rpc call*/

     /* This upcall is provided by the program during registration.

      * It is used to notify the program about events like connection being

@@ -696,4 +699,6 @@ rpcsvc_autoscale_threads(glusterfs_ctx_t *ctx, rpcsvc_t *rpc, int incr);

 extern int

 rpcsvc_destroy(rpcsvc_t *svc);

+void

+rpcsvc_statedump(rpcsvc_t *svc);

 #endif

diff --git a/xlators/protocol/server/src/server.c b/xlators/protocol/server/src/server.c

index 54d9c0f..90eb3ff 100644

--- a/xlators/protocol/server/src/server.c

+++ b/xlators/protocol/server/src/server.c

@@ -267,6 +267,8 @@ server_priv(xlator_t *this)

     gf_proc_dump_build_key(key, "server", "total-bytes-write");

     gf_proc_dump_write(key, "%" PRIu64, total_write);

+    rpcsvc_statedump(conf->rpc);

+

     ret = 0;

 out:

     if (ret)

-- 

1.8.3.1