From 8cc4b7874ed84802406575df8c447bb0bb525f34 Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Thu, 18 Jan 2018 09:52:59 +0100 Subject: [PATCH 1/6] Add statistics for requests per second --- daemon/call.c | 35 +++++++++++++++++++++++++++++++++++ daemon/cli.c | 25 +++++++++++++++++++++++++ daemon/control_ng.c | 6 ++++++ daemon/graphite.c | 41 +++++++++++++++++++++++++++++++++++++++++ daemon/statistics.h | 12 ++++++++++++ 5 files changed, 119 insertions(+) diff --git a/daemon/call.c b/daemon/call.c index 54a1da980..d0f11ddf2 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -460,6 +460,24 @@ destroy: atomic64_add(&ps->stats.x, d); \ atomic64_add(&m->statsps.x, d); \ } while (0) + +static void update_requests_per_second_stats(struct requests_ps *request, u_int64_t new_val) { + mutex_lock(&request->lock); + + request->count++; + request->ps_avg += new_val; + + if ((request->ps_min == 0) || (request->ps_min > new_val)) { + request->ps_min = new_val; + } + + if ((request->ps_max == 0) || (request->ps_max < new_val)) { + request->ps_max = new_val; + } + + mutex_unlock(&request->lock); +} + static void callmaster_timer(void *ptr) { struct callmaster *m = ptr; struct iterator_helper hlp; @@ -472,6 +490,7 @@ static void callmaster_timer(void *ptr) { struct rtp_stats *rs; unsigned int pt; endpoint_t ep; + int offers, answers, deletes; ZERO(hlp); hlp.addr_sfd = g_hash_table_new(g_endpoint_hash, g_endpoint_eq); @@ -498,6 +517,19 @@ static void callmaster_timer(void *ptr) { atomic64_set(&m->stats.packets, atomic64_get_na(&tmpstats.packets)); atomic64_set(&m->stats.errors, atomic64_get_na(&tmpstats.errors)); + /* update statistics regarding requests per second */ + offers = atomic64_get(&m->statsps.offers); + atomic64_set(&m->statsps.offers, 0); + update_requests_per_second_stats(&m->totalstats_interval.offers_ps, offers); + + answers = atomic64_get(&m->statsps.answers); + atomic64_set(&m->statsps.answers, 0); + update_requests_per_second_stats(&m->totalstats_interval.answers_ps, answers); + + deletes = atomic64_get(&m->statsps.deletes); + atomic64_set(&m->statsps.deletes, 0); + update_requests_per_second_stats(&m->totalstats_interval.deletes_ps, deletes); + i = kernel_list(); while (i) { ke = i->data; @@ -642,6 +674,9 @@ struct callmaster *callmaster_new(struct poller *p) { mutex_init(&c->cngs_lock); c->cngs_hash = g_hash_table_new(g_sockaddr_hash, g_sockaddr_eq); + mutex_init(&c->totalstats_interval.offers_ps.lock); + mutex_init(&c->totalstats_interval.answers_ps.lock); + mutex_init(&c->totalstats_interval.deletes_ps.lock); return c; fail: diff --git a/daemon/cli.c b/daemon/cli.c index 8ea48eaa5..7613b25dc 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -94,6 +94,7 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m struct timeval avg, calls_dur_iv; u_int64_t num_sessions, min_sess_iv, max_sess_iv; struct request_time offer_iv, answer_iv, delete_iv; + struct requests_ps offers_ps, answers_ps, deletes_ps; mutex_lock(&m->totalstats.total_average_lock); avg = m->totalstats.total_average_call_dur; @@ -136,12 +137,19 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m offer_iv = m->totalstats_lastinterval.offer; answer_iv = m->totalstats_lastinterval.answer; delete_iv = m->totalstats_lastinterval.delete; + offers_ps = m->totalstats_lastinterval.offers_ps; + answers_ps = m->totalstats_lastinterval.answers_ps; + deletes_ps = m->totalstats_lastinterval.deletes_ps; mutex_unlock(&m->totalstats_lastinterval_lock); // compute average offer/answer/delete time timeval_divide(&offer_iv.time_avg, &offer_iv.time_avg, offer_iv.count); timeval_divide(&answer_iv.time_avg, &answer_iv.time_avg, answer_iv.count); timeval_divide(&delete_iv.time_avg, &delete_iv.time_avg, delete_iv.count); + //compute average offers/answers/deletes per second + offers_ps.ps_avg = (offers_ps.count?(offers_ps.ps_avg/offers_ps.count):0); + answers_ps.ps_avg = (answers_ps.count?(answers_ps.ps_avg/answers_ps.count):0); + deletes_ps.ps_avg = (deletes_ps.count?(deletes_ps.ps_avg/deletes_ps.count):0); printlen = snprintf(replybuffer,(outbufend-replybuffer), "\nGraphite interval statistics (last reported values to graphite):\n"); ADJUSTLEN(printlen,outbufend,replybuffer); @@ -167,6 +175,23 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m (unsigned long long)delete_iv.time_avg.tv_sec,(unsigned long long)delete_iv.time_avg.tv_usec); ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg offer requests per second :%llu/%llu/%llu per sec\n", + (unsigned long long)offers_ps.ps_min, + (unsigned long long)offers_ps.ps_max, + (unsigned long long)offers_ps.ps_avg); + ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg answer requests per second :%llu/%llu/%llu per sec\n", + (unsigned long long)answers_ps.ps_min, + (unsigned long long)answers_ps.ps_max, + (unsigned long long)answers_ps.ps_avg); + ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg delete requests per second :%llu/%llu/%llu per sec\n", + (unsigned long long)deletes_ps.ps_min, + (unsigned long long)deletes_ps.ps_max, + (unsigned long long)deletes_ps.ps_avg); + ADJUSTLEN(printlen,outbufend,replybuffer); + + printlen = snprintf(replybuffer,(outbufend-replybuffer), "\n\n"); ADJUSTLEN(printlen,outbufend,replybuffer); diff --git a/daemon/control_ng.c b/daemon/control_ng.c index c956be322..fdb1f4574 100644 --- a/daemon/control_ng.c +++ b/daemon/control_ng.c @@ -176,6 +176,7 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin g_atomic_int_inc(&cur->ping); } else if (!str_cmp(&cmd, "offer")) { + //TODO inc offers per second // start offer timer gettimeofday(&offer_start, NULL); @@ -188,8 +189,10 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin // print offer duration timeval_from_us(&offer_stop, timeval_diff(&offer_stop, &offer_start)); ilog(LOG_INFO, "offer time = %llu.%06llu sec", (unsigned long long)offer_stop.tv_sec, (unsigned long long)offer_stop.tv_usec); + atomic64_inc(&c->callmaster->statsps.offers); } else if (!str_cmp(&cmd, "answer")) { + //TODO inc answers per second // start answer timer gettimeofday(&answer_start, NULL); @@ -202,8 +205,10 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin // print answer duration timeval_from_us(&answer_stop, timeval_diff(&answer_stop, &answer_start)); ilog(LOG_INFO, "answer time = %llu.%06llu sec", (unsigned long long)answer_stop.tv_sec, (unsigned long long)answer_stop.tv_usec); + atomic64_inc(&c->callmaster->statsps.answers); } else if (!str_cmp(&cmd, "delete")) { + //TODO inc deletes per second // start delete timer gettimeofday(&delete_start, NULL); @@ -216,6 +221,7 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin // print delete duration timeval_from_us(&delete_stop, timeval_diff(&delete_stop, &delete_start)); ilog(LOG_INFO, "delete time = %llu.%06llu sec", (unsigned long long)delete_stop.tv_sec, (unsigned long long)delete_stop.tv_usec); + atomic64_inc(&c->callmaster->statsps.deletes); } else if (!str_cmp(&cmd, "query")) { errstr = call_query_ng(dict, c->callmaster, resp); diff --git a/daemon/graphite.c b/daemon/graphite.c index 4003d5eb0..25f5f1867 100644 --- a/daemon/graphite.c +++ b/daemon/graphite.c @@ -38,6 +38,18 @@ void set_prefix(char* prefix) { graphite_prefix = prefix; } +static struct requests_ps clear_requests_per_second(struct requests_ps *requests) { + struct requests_ps ret; + mutex_lock(&requests->lock); + ret = *requests; + requests->count=0; + requests->ps_max = 0; + requests->ps_min = 0; + requests->ps_avg = 0; + mutex_unlock(&requests->lock); + return ret; +} + static struct request_time timeval_clear_request_time(struct request_time *request) { struct request_time ret; @@ -131,6 +143,10 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { ts->answer = timeval_clear_request_time(&cm->totalstats_interval.answer); ts->delete = timeval_clear_request_time(&cm->totalstats_interval.delete); + ts->offers_ps = clear_requests_per_second(&cm->totalstats_interval.offers_ps); + ts->answers_ps = clear_requests_per_second(&cm->totalstats_interval.answers_ps); + ts->deletes_ps = clear_requests_per_second(&cm->totalstats_interval.deletes_ps); + rwlock_lock_r(&cm->hashlock); mutex_lock(&cm->totalstats_interval.managed_sess_lock); ts->managed_sess_max = cm->totalstats_interval.managed_sess_max; @@ -147,6 +163,10 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { timeval_divide(&ts->offer.time_avg, &ts->offer.time_avg, ts->offer.count); timeval_divide(&ts->answer.time_avg, &ts->answer.time_avg, ts->answer.count); timeval_divide(&ts->delete.time_avg, &ts->delete.time_avg, ts->delete.count); + //compute average offers/answers/deletes per second + ts->offers_ps.ps_avg = (ts->offers_ps.count?(ts->offers_ps.ps_avg/ts->offers_ps.count):0); + ts->answers_ps.ps_avg = (ts->answers_ps.count?(ts->answers_ps.ps_avg/ts->answers_ps.count):0); + ts->deletes_ps.ps_avg = (ts->deletes_ps.count?(ts->deletes_ps.ps_avg/ts->deletes_ps.count):0); if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } rc = sprintf(ptr,"offer_time_min %llu.%06llu %llu\n",(unsigned long long)ts->offer.time_min.tv_sec,(unsigned long long)ts->offer.time_min.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; @@ -206,6 +226,27 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } rc = sprintf(ptr,"reject_sess "UINT64F" %llu\n", atomic64_get_na(&ts->total_rejected_sess),(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"offers_ps_min %llu %llu\n",(unsigned long long)ts->offers_ps.ps_min,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"offers_ps_max %llu %llu\n",(unsigned long long)ts->offers_ps.ps_max,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"offers_ps_avg %llu %llu\n",(unsigned long long)ts->offers_ps.ps_avg,(unsigned long long)g_now.tv_sec); ptr += rc; + + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answers_ps_min %llu %llu\n",(unsigned long long)ts->answers_ps.ps_min,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answers_ps_max %llu %llu\n",(unsigned long long)ts->answers_ps.ps_max,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answers_ps_avg %llu %llu\n",(unsigned long long)ts->answers_ps.ps_avg,(unsigned long long)g_now.tv_sec); ptr += rc; + + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"deletes_ps_min %llu %llu\n",(unsigned long long)ts->deletes_ps.ps_min,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"deletes_ps_max %llu %llu\n",(unsigned long long)ts->deletes_ps.ps_max,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"deletes_ps_avg %llu %llu\n",(unsigned long long)ts->deletes_ps.ps_avg,(unsigned long long)g_now.tv_sec); ptr += rc; + ilog(LOG_DEBUG, "min_sessions:%llu max_sessions:%llu, call_dur_per_interval:%llu.%06llu at time %llu\n", (unsigned long long) ts->managed_sess_min, (unsigned long long) ts->managed_sess_max, diff --git a/daemon/statistics.h b/daemon/statistics.h index 333a1e7ba..42311b2da 100644 --- a/daemon/statistics.h +++ b/daemon/statistics.h @@ -12,6 +12,9 @@ struct stats { u_int64_t delay_max; u_int8_t in_tos_tclass; /* XXX shouldn't be here - not stats */ atomic64 foreign_sessions; // unresponsible via redis notification + atomic64 offers; + atomic64 answers; + atomic64 deletes; }; @@ -21,6 +24,14 @@ struct request_time { struct timeval time_min, time_max, time_avg; }; +struct requests_ps { + mutex_t lock; + u_int64_t count; + u_int64_t ps_min; + u_int64_t ps_max; + u_int64_t ps_avg; +}; + struct totalstats { time_t started; @@ -52,6 +63,7 @@ struct totalstats { struct timeval total_calls_duration_interval; struct request_time offer, answer, delete; + struct requests_ps offers_ps, answers_ps, deletes_ps; }; struct rtp_stats { From 00bdcef9a4cd677d0c1ac36d83e4eed35917ef0c Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Fri, 19 Jan 2018 14:05:49 +0100 Subject: [PATCH 2/6] Fix statistics for average requests/sec sent to rtpengine-ctl --- daemon/cli.c | 4 ---- 1 file changed, 4 deletions(-) diff --git a/daemon/cli.c b/daemon/cli.c index ec63e6e73..2d51d2c7b 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -209,10 +209,6 @@ static void cli_incoming_list_totals(str *instr, struct streambuf *replybuffer) timeval_divide(&offer_iv.time_avg, &offer_iv.time_avg, offer_iv.count); timeval_divide(&answer_iv.time_avg, &answer_iv.time_avg, answer_iv.count); timeval_divide(&delete_iv.time_avg, &delete_iv.time_avg, delete_iv.count); - //compute average offers/answers/deletes per second - offers_ps.ps_avg = (offers_ps.count?(offers_ps.ps_avg/offers_ps.count):0); - answers_ps.ps_avg = (answers_ps.count?(answers_ps.ps_avg/answers_ps.count):0); - deletes_ps.ps_avg = (deletes_ps.count?(deletes_ps.ps_avg/deletes_ps.count):0); streambuf_printf(replybuffer, "\nGraphite interval statistics (last reported values to graphite):\n"); streambuf_printf(replybuffer, " Total calls duration :%ld.%06ld\n\n",calls_dur_iv.tv_sec,calls_dur_iv.tv_usec); From 3850e99fd319e4143560133bf6ad37e91c69dfd6 Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Thu, 25 Jan 2018 13:45:53 +0100 Subject: [PATCH 3/6] Use atomic64_get_set for requests statistics --- daemon/call.c | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) diff --git a/daemon/call.c b/daemon/call.c index 5f4c0af6a..0f8dbdaba 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -523,16 +523,13 @@ static void call_timer(void *ptr) { atomic64_set(&rtpe_stats.errors, atomic64_get_na(&tmpstats.errors)); /* update statistics regarding requests per second */ - offers = atomic64_get(&rtpe_statsps.offers); - atomic64_set(&rtpe_statsps.offers, 0); + offers = atomic64_get_set(&rtpe_statsps.offers, 0); update_requests_per_second_stats(&rtpe_totalstats_interval.offers_ps, offers); - answers = atomic64_get(&rtpe_statsps.answers); - atomic64_set(&rtpe_statsps.answers, 0); + answers = atomic64_get_set(&rtpe_statsps.answers, 0); update_requests_per_second_stats(&rtpe_totalstats_interval.answers_ps, answers); - deletes = atomic64_get(&rtpe_statsps.deletes); - atomic64_set(&rtpe_statsps.deletes, 0); + deletes = atomic64_get_set(&rtpe_statsps.deletes, 0); update_requests_per_second_stats(&rtpe_totalstats_interval.deletes_ps, deletes); i = kernel_list(); From 74cecc09a69f834ca8f19699b6f34be390ef8e90 Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Thu, 25 Jan 2018 14:26:31 +0100 Subject: [PATCH 4/6] Use statistics locks properly --- daemon/graphite.c | 2 +- daemon/statistics.c | 4 ++++ 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/daemon/graphite.c b/daemon/graphite.c index 69a8f9c50..c10845fed 100644 --- a/daemon/graphite.c +++ b/daemon/graphite.c @@ -350,7 +350,7 @@ void graphite_loop_run(endpoint_t *graphite_ep, int seconds) { connection_state = STATE_DISCONNECTED; } - copy_with_lock(&rtpe_totalstats_lastinterval, &graphite_stats, &rtpe_totalstats_lastinterval.total_average_lock); + copy_with_lock(&rtpe_totalstats_lastinterval, &graphite_stats, &rtpe_totalstats_lastinterval_lock); } } diff --git a/daemon/statistics.c b/daemon/statistics.c index e5570d3da..de7d9e70c 100644 --- a/daemon/statistics.c +++ b/daemon/statistics.c @@ -227,6 +227,10 @@ void statistics_init() { mutex_init(&rtpe_totalstats_lastinterval_lock); + mutex_init(&rtpe_totalstats_interval.offer.lock); + mutex_init(&rtpe_totalstats_interval.answer.lock); + mutex_init(&rtpe_totalstats_interval.delete.lock); + mutex_init(&rtpe_totalstats_interval.offers_ps.lock); mutex_init(&rtpe_totalstats_interval.answers_ps.lock); mutex_init(&rtpe_totalstats_interval.deletes_ps.lock); From 0ffb9e6718ed1f1cfcbfc0657d0bf3d0e1d0a6e7 Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Thu, 25 Jan 2018 15:04:28 +0100 Subject: [PATCH 5/6] Display correct average for requests statistics --- daemon/cli.c | 5 ----- 1 file changed, 5 deletions(-) diff --git a/daemon/cli.c b/daemon/cli.c index 2d51d2c7b..8fc148ea3 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -205,11 +205,6 @@ static void cli_incoming_list_totals(str *instr, struct streambuf *replybuffer) deletes_ps = rtpe_totalstats_lastinterval.deletes_ps; mutex_unlock(&rtpe_totalstats_lastinterval_lock); - // compute average offer/answer/delete time - timeval_divide(&offer_iv.time_avg, &offer_iv.time_avg, offer_iv.count); - timeval_divide(&answer_iv.time_avg, &answer_iv.time_avg, answer_iv.count); - timeval_divide(&delete_iv.time_avg, &delete_iv.time_avg, delete_iv.count); - streambuf_printf(replybuffer, "\nGraphite interval statistics (last reported values to graphite):\n"); streambuf_printf(replybuffer, " Total calls duration :%ld.%06ld\n\n",calls_dur_iv.tv_sec,calls_dur_iv.tv_usec); streambuf_printf(replybuffer, " Min managed sessions :"UINT64F"\n", min_sess_iv); From b7b40cc5a915f01df44a34d258f915139403cc5e Mon Sep 17 00:00:00 2001 From: Claudiu Boriga Date: Tue, 30 Jan 2018 09:21:09 +0100 Subject: [PATCH 6/6] Use proper data type for requests statistics --- daemon/call.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/daemon/call.c b/daemon/call.c index 0f8dbdaba..553970cf7 100644 --- a/daemon/call.c +++ b/daemon/call.c @@ -495,7 +495,7 @@ static void call_timer(void *ptr) { struct rtp_stats *rs; unsigned int pt; endpoint_t ep; - int offers, answers, deletes; + u_int64_t offers, answers, deletes; ZERO(hlp); hlp.addr_sfd = g_hash_table_new(g_endpoint_hash, g_endpoint_eq);