From 57aa56616d65493cc38c11bedf8e1f5f7869364a Mon Sep 17 00:00:00 2001 From: Stefan Mititelu Date: Mon, 14 Mar 2016 14:06:02 +0100 Subject: [PATCH] Add offer/answer/delete processing statistics Add graphite offer/answer/delete min/max/avg statistics. Print new graphite statistics in rtpengine-cli list totals. --- daemon/aux.h | 5 ++++ daemon/call.h | 8 ++++++ daemon/cli.c | 33 +++++++++++++++++++++++ daemon/control_ng.c | 66 +++++++++++++++++++++++++++++++++++++++++++++ daemon/graphite.c | 61 ++++++++++++++++++++++++++++++++++++++++- 5 files changed, 172 insertions(+), 1 deletion(-) diff --git a/daemon/aux.h b/daemon/aux.h index afbae0deb..ac4710947 100644 --- a/daemon/aux.h +++ b/daemon/aux.h @@ -567,6 +567,11 @@ INLINE void timeval_multiply(struct timeval *result, const struct timeval *a, co timeval_from_us(result, timeval_us(a) * multiplier); } INLINE void timeval_divide(struct timeval *result, const struct timeval *a, const long divisor) { + if (divisor == 0) { + result->tv_sec = 0; + result->tv_usec = 0; + return ; + } timeval_from_us(result, timeval_us(a) / divisor); } INLINE void timeval_add(struct timeval *result, const struct timeval *a, const struct timeval *b) { diff --git a/daemon/call.h b/daemon/call.h index 28f5c26e0..c66f09676 100644 --- a/daemon/call.h +++ b/daemon/call.h @@ -231,6 +231,12 @@ struct stats { u_int8_t in_tos_tclass; /* XXX shouldn't be here - not stats */ }; +struct request_time { + mutex_t lock; + u_int64_t count; + struct timeval time_min, time_max, time_avg; +}; + struct totalstats { time_t started; atomic64 total_timeout_sess; @@ -254,6 +260,8 @@ struct totalstats { mutex_t total_calls_duration_lock; /* for these two below */ struct timeval total_calls_duration_interval; + + struct request_time offer, answer, delete; }; struct stream_params { diff --git a/daemon/cli.c b/daemon/cli.c index ad831ffe8..e01e7aafd 100644 --- a/daemon/cli.c +++ b/daemon/cli.c @@ -21,6 +21,7 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m int printlen=0; struct timeval avg, calls_dur_iv; u_int64_t num_sessions, min_sess_iv, max_sess_iv; + struct request_time offer, answer, delete; mutex_lock(&m->totalstats.total_average_lock); avg = m->totalstats.total_average_call_dur; @@ -60,6 +61,23 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m max_sess_iv = m->totalstats_lastinterval.managed_sess_max; mutex_unlock(&m->totalstats_lastinterval_lock); + mutex_lock(&m->totalstats_interval.offer.lock); + offer = m->totalstats_interval.offer; + mutex_unlock(&m->totalstats_interval.offer.lock); + + mutex_lock(&m->totalstats_interval.answer.lock); + answer = m->totalstats_interval.answer; + mutex_unlock(&m->totalstats_interval.answer.lock); + + mutex_lock(&m->totalstats_interval.delete.lock); + delete = m->totalstats_interval.delete; + mutex_unlock(&m->totalstats_interval.delete.lock); + + // compute average offer/answer/delete time + timeval_divide(&offer.time_avg, &offer.time_avg, offer.count); + timeval_divide(&answer.time_avg, &answer.time_avg, answer.count); + timeval_divide(&delete.time_avg, &delete.time_avg, delete.count); + printlen = snprintf(replybuffer,(outbufend-replybuffer), "\nGraphite interval statistics (last reported values to graphite):\n"); ADJUSTLEN(printlen,outbufend,replybuffer); printlen = snprintf(replybuffer,(outbufend-replybuffer), " Total calls duration :%ld.%06ld\n\n",calls_dur_iv.tv_sec,calls_dur_iv.tv_usec); @@ -68,6 +86,21 @@ static void cli_incoming_list_totals(char* buffer, int len, struct callmaster* m ADJUSTLEN(printlen,outbufend,replybuffer); printlen = snprintf(replybuffer,(outbufend-replybuffer), " Max managed sessions :"UINT64F"\n", max_sess_iv); ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg offer processing delay :%llu.%06llu/%llu.%06llu/%llu.%06llu sec\n", + (unsigned long long)offer.time_min.tv_sec,(unsigned long long)offer.time_min.tv_usec, + (unsigned long long)offer.time_max.tv_sec,(unsigned long long)offer.time_max.tv_usec, + (unsigned long long)offer.time_avg.tv_sec,(unsigned long long)offer.time_avg.tv_usec); + ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg answer processing delay :%llu.%06llu/%llu.%06llu/%llu.%06llu sec\n", + (unsigned long long)answer.time_min.tv_sec,(unsigned long long)answer.time_min.tv_usec, + (unsigned long long)answer.time_max.tv_sec,(unsigned long long)answer.time_max.tv_usec, + (unsigned long long)answer.time_avg.tv_sec,(unsigned long long)answer.time_avg.tv_usec); + ADJUSTLEN(printlen,outbufend,replybuffer); + printlen = snprintf(replybuffer,(outbufend-replybuffer), " Min/Max/Avg delete processing delay :%llu.%06llu/%llu.%06llu/%llu.%06llu sec\n", + (unsigned long long)delete.time_min.tv_sec,(unsigned long long)delete.time_min.tv_usec, + (unsigned long long)delete.time_max.tv_sec,(unsigned long long)delete.time_max.tv_usec, + (unsigned long long)delete.time_avg.tv_sec,(unsigned long long)delete.time_avg.tv_usec); + 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 1f9735a47..31d924c11 100644 --- a/daemon/control_ng.c +++ b/daemon/control_ng.c @@ -13,6 +13,30 @@ #include "call_interfaces.h" #include "socket.h" +static void timeval_update_request_time(struct request_time *request, const struct timeval *offer_diff) { + // lock offers + mutex_lock(&request->lock); + + // update min value + if (timeval_us(&request->time_min) == 0 || + timeval_cmp(&request->time_min, offer_diff) > 0) { + timeval_from_us(&request->time_min, timeval_us(offer_diff)); + } + + // update max value + if (timeval_us(&request->time_max) == 0 || + timeval_cmp(&request->time_max, offer_diff) < 0) { + timeval_from_us(&request->time_max, timeval_us(offer_diff)); + } + + // update avg value + timeval_add(&request->time_avg, &request->time_avg, offer_diff); + request->count++; + + // unlock offers + mutex_unlock(&request->lock); +} + static void pretty_print(bencode_item_t *el, GString *s) { bencode_item_t *chld; @@ -86,6 +110,9 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin struct iovec iov[3]; unsigned int iovlen; GString *log_str; + struct timeval offer_start, offer_stop; + struct timeval answer_start, answer_stop; + struct timeval delete_start, delete_stop; struct control_ng_stats* cur = get_control_ng_stats(c,&sin->address); @@ -143,16 +170,46 @@ 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")) { + // start offer timer + gettimeofday(&offer_start, NULL); + errstr = call_offer_ng(dict, c->callmaster, resp, addr, sin); g_atomic_int_inc(&cur->offer); + + // stop offer timer + gettimeofday(&offer_stop, NULL); + + // 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); } else if (!str_cmp(&cmd, "answer")) { + // start answer timer + gettimeofday(&answer_start, NULL); + errstr = call_answer_ng(dict, c->callmaster, resp); g_atomic_int_inc(&cur->answer); + + // stop answer timer + gettimeofday(&answer_stop, NULL); + + // 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); } else if (!str_cmp(&cmd, "delete")) { + // start delete timer + gettimeofday(&delete_start, NULL); + errstr = call_delete_ng(dict, c->callmaster, resp); g_atomic_int_inc(&cur->delete); + + // stop delete timer + gettimeofday(&delete_stop, NULL); + + // 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); } else if (!str_cmp(&cmd, "query")) { errstr = call_query_ng(dict, c->callmaster, resp); @@ -168,6 +225,15 @@ static void control_ng_incoming(struct obj *obj, str *buf, const endpoint_t *sin if (errstr) goto err_send; + // update interval statistics + if (!str_cmp(&cmd, "offer")) { + timeval_update_request_time(&c->callmaster->totalstats_interval.offer, &offer_stop); + } else if (!str_cmp(&cmd, "answer")) { + timeval_update_request_time(&c->callmaster->totalstats_interval.answer, &answer_stop); + } else if (!str_cmp(&cmd, "delete")) { + timeval_update_request_time(&c->callmaster->totalstats_interval.delete, &delete_stop); + } + goto send_resp; err_send: diff --git a/daemon/graphite.c b/daemon/graphite.c index 66bf28add..74407fbba 100644 --- a/daemon/graphite.c +++ b/daemon/graphite.c @@ -37,6 +37,23 @@ void set_prefix(char* prefix) { graphite_prefix = prefix; } +static struct request_time timeval_clear_request_time(struct request_time *request) { + struct request_time ret; + + mutex_lock(&request->lock); + ret = *request; + request->time_min.tv_sec = 0; + request->time_min.tv_usec = 0; + request->time_max.tv_sec = 0; + request->time_max.tv_usec = 0; + request->time_avg.tv_sec = 0; + request->time_avg.tv_usec = 0; + request->count = 0; + mutex_unlock(&request->lock); + + return ret; +} + int connect_to_graphite_server(const endpoint_t *graphite_ep) { int rc; @@ -105,10 +122,13 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { ts->total_calls_duration_interval = cm->totalstats_interval.total_calls_duration_interval; cm->totalstats_interval.total_calls_duration_interval.tv_sec = 0; cm->totalstats_interval.total_calls_duration_interval.tv_usec = 0; - //ZERO(cm->totalstats_interval.total_calls_duration_interval); mutex_unlock(&cm->totalstats_interval.total_calls_duration_lock); + ts->offer = timeval_clear_request_time(&cm->totalstats_interval.offer); + ts->answer = timeval_clear_request_time(&cm->totalstats_interval.answer); + ts->delete = timeval_clear_request_time(&cm->totalstats_interval.delete); + rwlock_lock_r(&cm->hashlock); mutex_lock(&cm->totalstats_interval.managed_sess_lock); ts->managed_sess_max = cm->totalstats_interval.managed_sess_max; @@ -118,6 +138,32 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { mutex_unlock(&cm->totalstats_interval.managed_sess_lock); rwlock_unlock_r(&cm->hashlock); + // compute average offer/answer/delete time + 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); + + 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; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"offer_time_max %llu.%06llu %llu\n",(unsigned long long)ts->offer.time_max.tv_sec,(unsigned long long)ts->offer.time_max.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"offer_time_avg %llu.%06llu %llu\n",(unsigned long long)ts->offer.time_avg.tv_sec,(unsigned long long)ts->offer.time_avg.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answer_time_min %llu.%06llu %llu\n",(unsigned long long)ts->answer.time_min.tv_sec,(unsigned long long)ts->answer.time_min.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answer_time_max %llu.%06llu %llu\n",(unsigned long long)ts->answer.time_max.tv_sec,(unsigned long long)ts->answer.time_max.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"answer_time_avg %llu.%06llu %llu\n",(unsigned long long)ts->answer.time_avg.tv_sec,(unsigned long long)ts->answer.time_avg.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"delete_time_min %llu.%06llu %llu\n",(unsigned long long)ts->delete.time_min.tv_sec,(unsigned long long)ts->delete.time_min.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"delete_time_max %llu.%06llu %llu\n",(unsigned long long)ts->delete.time_max.tv_sec,(unsigned long long)ts->delete.time_max.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } + rc = sprintf(ptr,"delete_time_avg %llu.%06llu %llu\n",(unsigned long long)ts->delete.time_avg.tv_sec,(unsigned long long)ts->delete.time_avg.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; + if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } rc = sprintf(ptr, "call_dur %llu.%06llu %llu\n",(unsigned long long)ts->total_calls_duration_interval.tv_sec,(unsigned long long)ts->total_calls_duration_interval.tv_usec,(unsigned long long)g_now.tv_sec); ptr += rc; if (graphite_prefix!=NULL) { rc = sprintf(ptr,"%s",graphite_prefix); ptr += rc; } @@ -154,6 +200,19 @@ int send_graphite_data(struct callmaster *cm, struct totalstats *sent_data) { (unsigned long long ) ts->total_calls_duration_interval.tv_usec, (unsigned long long ) g_now.tv_sec); + ilog(LOG_DEBUG, "Min/Max/Avg offer processing delay: %llu.%06llu/%llu.%06llu/%llu.%06llu sec", + (unsigned long long)ts->offer.time_min.tv_sec,(unsigned long long)ts->offer.time_min.tv_usec, + (unsigned long long)ts->offer.time_max.tv_sec,(unsigned long long)ts->offer.time_max.tv_usec, + (unsigned long long)ts->offer.time_avg.tv_sec,(unsigned long long)ts->offer.time_avg.tv_usec); + ilog(LOG_DEBUG, "Min/Max/Avg answer processing delay: %llu.%06llu/%llu.%06llu/%llu.%06llu sec", + (unsigned long long)ts->answer.time_min.tv_sec,(unsigned long long)ts->answer.time_min.tv_usec, + (unsigned long long)ts->answer.time_max.tv_sec,(unsigned long long)ts->answer.time_max.tv_usec, + (unsigned long long)ts->answer.time_avg.tv_sec,(unsigned long long)ts->answer.time_avg.tv_usec); + ilog(LOG_DEBUG, "Min/Max/Avg delete processing delay: %llu.%06llu/%llu.%06llu/%llu.%06llu sec", + (unsigned long long)ts->delete.time_min.tv_sec,(unsigned long long)ts->delete.time_min.tv_usec, + (unsigned long long)ts->delete.time_max.tv_sec,(unsigned long long)ts->delete.time_max.tv_usec, + (unsigned long long)ts->delete.time_avg.tv_sec,(unsigned long long)ts->delete.time_avg.tv_usec); + rc = write(graphite_sock.fd, data_to_send, ptr - data_to_send); if (rc<0) { ilog(LOG_ERROR,"Could not write to graphite socket. Disconnecting graphite server.");