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>

3 files changed, 76 insertions, 2 deletions

diff --git a/rpc/rpc-lib/src/libgfrpc.sym b/rpc/rpc-lib/src/libgfrpc.sym
index 54d1be1112f..e026d80259b 100644
--- a/rpc/rpc-lib/src/libgfrpc.sym
+++ b/rpc/rpc-lib/src/libgfrpc.sym
@@ -65,3 +65,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 9e8c9af8a12..39910d481bf 100644
--- a/rpc/rpc-lib/src/rpcsvc.c
+++ b/rpc/rpc-lib/src/rpcsvc.c
@@ -13,6 +13,7 @@
 #include <glusterfs/dict.h>
 #include <glusterfs/byte-order.h>
 #include <glusterfs/compat-errno.h>
+#include <glusterfs/statedump.h>
 #include "xdr-rpc.h"
 #include <glusterfs/iobuf.h>
 #include "xdr-common.h"
@@ -341,6 +342,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;
 
@@ -1490,10 +1495,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++) {
@@ -1824,6 +1837,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)
 {
@@ -1881,8 +1903,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) {
@@ -2267,6 +2288,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);
@@ -3212,6 +3238,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);
+}
+
 static rpcsvc_actor_t gluster_dump_actors[GF_DUMP_MAXVALUE] = {
     [GF_DUMP_NULL] = {"NULL", NULL, NULL, GF_DUMP_NULL, DRC_NA, 0},
     [GF_DUMP_DUMP] = {"DUMP", rpcsvc_dump, NULL, GF_DUMP_DUMP, DRC_NA, 0},
diff --git a/rpc/rpc-lib/src/rpcsvc.h b/rpc/rpc-lib/src/rpcsvc.h
index c370b330572..7b3030926c8 100644
--- a/rpc/rpc-lib/src/rpcsvc.h
+++ b/rpc/rpc-lib/src/rpcsvc.h
@@ -264,6 +264,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))
@@ -419,6 +421,7 @@ struct rpcsvc_program {
                                supported by the system. */
     /* 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
@@ -686,4 +689,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