From 0935afb947e520fd8e41ebfc311888eafc6afdc0 Mon Sep 17 00:00:00 2001 From: Pranith Kumar K Date: Fri, 4 Sep 2020 10:44:17 +0530 Subject: 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 --- rpc/rpc-lib/src/libgfrpc.sym | 1 + rpc/rpc-lib/src/rpcsvc.c | 72 ++++++++++++++++++++++++++++++++++++++++++-- rpc/rpc-lib/src/rpcsvc.h | 5 +++ 3 files changed, 76 insertions(+), 2 deletions(-) (limited to 'rpc') 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 #include #include +#include #include "xdr-rpc.h" #include #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 -- cgit