sipwise
/
rtpengine
mirror of https://github.com/sipwise/rtpengine.git
1
0
Fork 0
Code Issues Releases Wiki Activity

Add offer/answer/delete processing statistics

Browse Source 
Add graphite offer/answer/delete min/max/avg statistics.
Print new graphite statistics in rtpengine-cli list totals.
pull/231/head
Stefan Mititelu 10 years ago
parent 926d9d3963
commit 57aa56616d
5 changed files with 172 additions and 1 deletions
Show Stats Download Patch File Download Diff File

5
daemon/aux.h
Unescape View File

@ -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) {

8
daemon/call.h
Unescape View File

@ -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 {

33
daemon/cli.c
Unescape View File

@ -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);

66
daemon/control_ng.c
Unescape View File

@ -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:

61
daemon/graphite.c
Unescape View File

@ -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.");

Write Preview
Loading…
Cancel
Save