From 76b5be4c8796c41b189eb0e72b047f9e60c9fe3c Mon Sep 17 00:00:00 2001
From: Mark Spencer <markster@digium.com>
Date: Sun, 24 Oct 2004 04:54:42 +0000
Subject: [PATCH] DUNDi performance enhancments and metrics for average lookup
time.
git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@4073 65c4cc65-6c06-0410-ace0-fbb531ad65f3
---
configs/dundi.conf.sample | 9 +++
pbx/pbx_dundi.c | 161 ++++++++++++++++++++++++++++++++++----
2 files changed, 156 insertions(+), 14 deletions(-)
diff --git a/configs/dundi.conf.sample b/configs/dundi.conf.sample
index 39dda3dfd7..a435af847a 100755
--- a/configs/dundi.conf.sample
+++ b/configs/dundi.conf.sample
@@ -52,6 +52,15 @@ autokill=yes
; the key being held at dundi/secret).
;
;secretpath=dundi
+;
+; The 'storehistory' option (also changeable at runtime with
+; 'dundi store history' and 'dundi no store history') will
+; cause the DUNDi engine to keep track of the last several
+; queries and the amount of time each query took to execute
+; for the purpose of tracking slow nodes. This option is
+; off by default due to performance impacts.
+;
+;slowhistory=yes
[mappings]
;
diff --git a/pbx/pbx_dundi.c b/pbx/pbx_dundi.c
index 89e18dfa08..1b2ed775ef 100755
--- a/pbx/pbx_dundi.c
+++ b/pbx/pbx_dundi.c
@@ -77,6 +77,8 @@ static char *descrip =
#define DUNDI_MODEL_OUTBOUND (1 << 1)
#define DUNDI_MODEL_SYMMETRIC (DUNDI_MODEL_INBOUND | DUNDI_MODEL_OUTBOUND)
+/* Keep times of last 10 lookups */
+#define DUNDI_TIMING_HISTORY 10
#define FLAG_ISREG (1 << 0) /* Transaction is register request */
#define FLAG_DEAD (1 << 1) /* Transaction is dead */
@@ -84,6 +86,7 @@ static char *descrip =
#define FLAG_ISQUAL (1 << 3) /* Transaction is a qualification */
#define FLAG_ENCRYPT (1 << 4) /* Transaction is encrypted wiht ECX/DCX */
#define FLAG_SENDFULLKEY (1 << 5) /* Send full key on transaction */
+#define FLAG_STOREHIST (1 << 6) /* Record historic performance */
#define DUNDI_FLAG_INTERNAL_NOPARTIAL (1 << 17)
@@ -108,6 +111,7 @@ static int dundi_key_ttl = DUNDI_DEFAULT_KEY_EXPIRE;
static int global_autokilltimeout = 0;
static dundi_eid global_eid;
static int default_expiration = 60;
+static int global_storehistory = 0;
static char dept[80];
static char org[80];
static char locality[80];
@@ -145,6 +149,7 @@ struct dundi_request;
struct dundi_transaction {
struct sockaddr_in addr; /* Other end of transaction */
+ struct timeval start; /* When this transaction was created */
dundi_eid eids[DUNDI_MAX_STACK + 1];
int eidcount; /* Number of eids in eids */
dundi_eid us_eid; /* Our EID, to them */
@@ -154,6 +159,7 @@ struct dundi_transaction {
int flags; /* Has final packet been sent */
int ttl; /* Remaining TTL for queries on this one */
int thread; /* We have a calling thread */
+ int retranstimer; /* How long to wait before retransmissions */
int autokillid; /* ID to kill connection if answer doesn't come back fast enough */
int autokilltimeout; /* Recommended timeout for autokill */
unsigned short strans; /* Our transaction identifier */
@@ -180,6 +186,7 @@ struct dundi_request {
int maxcount;
int respcount;
int expiration;
+ int pfds[2];
unsigned long crc32; /* CRC-32 of all but root EID's in avoid list */
struct dundi_transaction *trans; /* Transactions */
struct dundi_request *next;
@@ -220,6 +227,9 @@ static struct dundi_peer {
aes_decrypt_ctx them_dcx; /* Cached AES 128 Decryption context */
time_t keyexpire; /* When to expire/recreate key */
int registerexpire;
+ int lookuptimes[DUNDI_TIMING_HISTORY];
+ char *lookups[DUNDI_TIMING_HISTORY];
+ int avgms;
struct dundi_transaction *regtrans; /* Registration transaction */
struct dundi_transaction *qualtrans; /* Qualify transaction */
struct dundi_transaction *keypending;
@@ -1029,9 +1039,17 @@ static void apply_peer(struct dundi_transaction *trans, struct dundi_peer *p)
/* Enable encryption if appropriate */
if (!ast_strlen_zero(p->inkey))
trans->flags |= FLAG_ENCRYPT;
- if (p->maxms)
+ if (p->maxms) {
trans->autokilltimeout = p->maxms;
- else
+ if (p->lastms > 1) {
+ trans->retranstimer = p->lastms * 2;
+ if (trans->retranstimer > DUNDI_DEFAULT_RETRANS_TIMER)
+ trans->retranstimer = DUNDI_DEFAULT_RETRANS_TIMER;
+ /* Keep it from being silly */
+ if (trans->retranstimer < 10)
+ trans->retranstimer = 10;
+ }
+ } else
trans->autokilltimeout = global_autokilltimeout;
}
@@ -1940,6 +1958,15 @@ static int dundi_do_debug(int fd, int argc, char *argv[])
return RESULT_SUCCESS;
}
+static int dundi_do_store_history(int fd, int argc, char *argv[])
+{
+ if (argc != 3)
+ return RESULT_SHOWUSAGE;
+ dundidebug = 1;
+ ast_cli(fd, "DUNDi History Storage Enabled\n");
+ return RESULT_SUCCESS;
+}
+
static int dundi_flush(int fd, int argc, char *argv[])
{
if (argc != 2)
@@ -1958,6 +1985,15 @@ static int dundi_no_debug(int fd, int argc, char *argv[])
return RESULT_SUCCESS;
}
+static int dundi_no_store_history(int fd, int argc, char *argv[])
+{
+ if (argc != 3)
+ return RESULT_SHOWUSAGE;
+ dundidebug = 0;
+ ast_cli(fd, "DUNDi History Storage Disabled\n");
+ return RESULT_SUCCESS;
+}
+
static char *model2str(int model)
{
switch(model) {
@@ -2027,6 +2063,7 @@ static int dundi_do_lookup(int fd, int argc, char *argv[])
char *context;
int x;
struct dundi_result dr[MAX_RESULTS];
+ struct timeval start;
if ((argc < 3) || (argc > 3))
return RESULT_SHOWUSAGE;
strncpy(tmp, argv[2], sizeof(tmp) - 1);
@@ -2035,7 +2072,9 @@ static int dundi_do_lookup(int fd, int argc, char *argv[])
*context = '\0';
context++;
}
+ gettimeofday(&start, NULL);
res = dundi_lookup(dr, MAX_RESULTS, NULL, context, tmp);
+
if (res < 0)
ast_cli(fd, "DUNDi lookup returned error.\n");
else if (!res)
@@ -2045,6 +2084,7 @@ static int dundi_do_lookup(int fd, int argc, char *argv[])
for (x=0;x<res;x++) {
ast_cli(fd, "%d. %5d %s/%s (%s)\n", x + 1, dr[x].weight, dr[x].tech, dr[x].dest, dundi_flags2str(fs, sizeof(fs), dr[x].flags));
}
+ ast_cli(fd, "DUNDi lookup completed in %d ms\n", calc_ms(&start));
return RESULT_SUCCESS;
}
@@ -2093,6 +2133,7 @@ static int dundi_show_peer(int fd, int argc, char *argv[])
char *order;
char iabuf[INET_ADDRSTRLEN];
char eid_str[20];
+ int x, cnt;
if (argc != 4)
return RESULT_SHOWUSAGE;
@@ -2144,7 +2185,17 @@ static int dundi_show_peer(int fd, int argc, char *argv[])
ast_cli(fd, "-- %s %s\n", p->allow ? "permit" : "deny", p->name);
p = p->next;
}
-
+ cnt = 0;
+ for (x=0;x<DUNDI_TIMING_HISTORY;x++) {
+ if (peer->lookups[x]) {
+ if (!cnt)
+ ast_cli(fd, "Last few query times:\n");
+ ast_cli(fd, "-- %d. %s (%d ms)\n", x + 1, peer->lookups[x], peer->lookuptimes[x]);
+ cnt++;
+ }
+ }
+ if (cnt)
+ ast_cli(fd, "Average query time: %d ms\n", peer->avgms);
} else
ast_cli(fd, "No such peer '%s'\n", argv[3]);
ast_mutex_unlock(&peerlock);
@@ -2153,11 +2204,12 @@ static int dundi_show_peer(int fd, int argc, char *argv[])
static int dundi_show_peers(int fd, int argc, char *argv[])
{
-#define FORMAT2 "%-20.20s %-15.15s %-15.15s %-15.15s\n"
-#define FORMAT "%-20.20s %-15.15s %s %-15.15s %-15.15s\n"
+#define FORMAT2 "%-20.20s %-15.15s %-10.10s %-8.8s %-15.15s\n"
+#define FORMAT "%-20.20s %-15.15s %s %-10.10s %-8.8s %-15.15s\n"
struct dundi_peer *peer;
char iabuf[INET_ADDRSTRLEN];
int registeredonly=0;
+ char avgms[20];
char eid_str[20];
if ((argc != 3) && (argc != 4) && (argc != 5))
return RESULT_SHOWUSAGE;
@@ -2168,7 +2220,7 @@ static int dundi_show_peers(int fd, int argc, char *argv[])
return RESULT_SHOWUSAGE;
}
ast_mutex_lock(&peerlock);
- ast_cli(fd, FORMAT2, "EID", "Host", "Model", "Status");
+ ast_cli(fd, FORMAT2, "EID", "Host", "Model", "AvgTime", "Status");
for (peer = peers;peer;peer = peer->next) {
char status[20] = "";
int print_line = -1;
@@ -2186,10 +2238,13 @@ static int dundi_show_peers(int fd, int argc, char *argv[])
strncpy(status, "UNKNOWN", sizeof(status) - 1);
} else
strncpy(status, "Unmonitored", sizeof(status) - 1);
-
+ if (peer->avgms)
+ snprintf(avgms, sizeof(avgms), "%d ms", peer->avgms);
+ else
+ strcpy(avgms, "Unavail");
snprintf(srch, sizeof(srch), FORMAT, dundi_eid_to_str(eid_str, sizeof(eid_str), &peer->eid),
peer->addr.sin_addr.s_addr ? ast_inet_ntoa(iabuf, sizeof(iabuf), peer->addr.sin_addr) : "(Unspecified)",
- peer->dynamic ? "(D)" : "(S)", model2str(peer->model), status);
+ peer->dynamic ? "(D)" : "(S)", model2str(peer->model), avgms, status);
if (argc == 5) {
if (!strcasecmp(argv[3],"include") && strstr(srch,argv[4])) {
@@ -2206,7 +2261,7 @@ static int dundi_show_peers(int fd, int argc, char *argv[])
if (print_line) {
ast_cli(fd, FORMAT, dundi_eid_to_str(eid_str, sizeof(eid_str), &peer->eid),
peer->addr.sin_addr.s_addr ? ast_inet_ntoa(iabuf, sizeof(iabuf), peer->addr.sin_addr) : "(Unspecified)",
- peer->dynamic ? "(D)" : "(S)", model2str(peer->model), status);
+ peer->dynamic ? "(D)" : "(S)", model2str(peer->model), avgms, status);
}
}
ast_mutex_unlock(&peerlock);
@@ -2298,6 +2353,16 @@ static char no_debug_usage[] =
"Usage: dundi no debug\n"
" Disables dumping of DUNDi packets for debugging purposes\n";
+static char store_history_usage[] =
+"Usage: dundi store history\n"
+" Enables storing of DUNDi requests and times for debugging\n"
+"purposes\n";
+
+static char no_store_history_usage[] =
+"Usage: dundi no store history\n"
+" Disables storing of DUNDi requests and times for debugging\n"
+"purposes\n";
+
static char show_peers_usage[] =
"Usage: dundi show peers\n"
" Lists all known DUNDi peers.\n";
@@ -2341,6 +2406,12 @@ static char flush_usage[] =
static struct ast_cli_entry cli_debug =
{ { "dundi", "debug", NULL }, dundi_do_debug, "Enable DUNDi debugging", debug_usage };
+static struct ast_cli_entry cli_store_history =
+ { { "dundi", "store", "history", NULL }, dundi_do_store_history, "Enable DUNDi historic records", store_history_usage };
+
+static struct ast_cli_entry cli_no_store_history =
+ { { "dundi", "no", "store", "history", NULL }, dundi_no_store_history, "Disable DUNDi historic records", no_store_history_usage };
+
static struct ast_cli_entry cli_flush =
{ { "dundi", "flush", NULL }, dundi_flush, "Flush DUNDi cache", flush_usage };
@@ -2389,6 +2460,11 @@ static struct dundi_transaction *create_transaction(struct dundi_peer *p)
trans = malloc(sizeof(struct dundi_transaction));
if (trans) {
memset(trans, 0, sizeof(struct dundi_transaction));
+ if (global_storehistory) {
+ gettimeofday(&trans->start, NULL);
+ trans->flags |= FLAG_STOREHIST;
+ }
+ trans->retranstimer = DUNDI_DEFAULT_RETRANS_TIMER;
trans->autokillid = -1;
if (p) {
apply_peer(trans, p);
@@ -2453,8 +2529,10 @@ static void destroy_trans(struct dundi_transaction *trans, int fromtimeout)
struct dundi_peer *peer;
struct timeval tv;
int ms;
+ int x;
+ int cnt;
char eid_str[20];
- if (trans->flags & (FLAG_ISREG | FLAG_ISQUAL)) {
+ if (trans->flags & (FLAG_ISREG | FLAG_ISQUAL | FLAG_STOREHIST)) {
peer = peers;
while (peer) {
if (peer->regtrans == trans)
@@ -2482,6 +2560,33 @@ static void destroy_trans(struct dundi_transaction *trans, int fromtimeout)
}
peer->qualtrans = NULL;
}
+ if (trans->flags & FLAG_STOREHIST) {
+ if (trans->parent) {
+ if (!dundi_eid_cmp(&trans->them_eid, &peer->eid)) {
+ peer->avgms = 0;
+ cnt = 0;
+ if (peer->lookups[DUNDI_TIMING_HISTORY-1])
+ free(peer->lookups[DUNDI_TIMING_HISTORY-1]);
+ for (x=DUNDI_TIMING_HISTORY-1;x>0;x--) {
+ peer->lookuptimes[x] = peer->lookuptimes[x-1];
+ peer->lookups[x] = peer->lookups[x-1];
+ if (peer->lookups[x]) {
+ peer->avgms += peer->lookuptimes[x];
+ cnt++;
+ }
+ }
+ peer->lookuptimes[0] = calc_ms(&trans->start);
+ peer->lookups[0] = malloc(strlen(trans->parent->number) + strlen(trans->parent->dcontext) + 2);
+ if (peer->lookups[0]) {
+ sprintf(peer->lookups[0], "%s@%s", trans->parent->number, trans->parent->dcontext);
+ peer->avgms += peer->lookuptimes[0];
+ cnt++;
+ }
+ if (cnt)
+ peer->avgms /= cnt;
+ }
+ }
+ }
peer = peer->next;
}
}
@@ -2500,6 +2605,12 @@ static void destroy_trans(struct dundi_transaction *trans, int fromtimeout)
prev = cur;
cur = cur->next;
}
+ if (!trans->parent->trans) {
+ /* Wake up sleeper */
+ if (trans->parent->pfds[1] > -1) {
+ write(trans->parent->pfds[1], "killa!", 6);
+ }
+ }
}
/* Unlink from all trans */
prev = NULL;
@@ -2568,7 +2679,7 @@ static int dundi_send(struct dundi_transaction *trans, int cmdresp, int flags, i
memset(pack, 0, len);
pack->h = (struct dundi_hdr *)(pack->data);
if (cmdresp != DUNDI_COMMAND_ACK) {
- pack->retransid = ast_sched_add(sched, DUNDI_DEFAULT_RETRANS_TIMER, dundi_rexmit, pack);
+ pack->retransid = ast_sched_add(sched, trans->retranstimer, dundi_rexmit, pack);
pack->retrans = DUNDI_DEFAULT_RETRANS - 1;
pack->next = trans->packets;
trans->packets = pack;
@@ -2976,6 +3087,7 @@ static int dundi_lookup_internal(struct dundi_result *result, int maxret, struct
dundi_eid *rooteid=NULL;
int x;
int ttlms;
+ int ms;
int foundcache;
int skipped=0;
int order=0;
@@ -2992,6 +3104,10 @@ static int dundi_lookup_internal(struct dundi_result *result, int maxret, struct
rooteid = avoid[x];
/* Now perform real check */
memset(&dr, 0, sizeof(dr));
+ if (pipe(dr.pfds)) {
+ ast_log(LOG_WARNING, "pipe failed: %s\n" , strerror(errno));
+ return -1;
+ }
dr.dr = result;
dr.hmd = hmd;
dr.maxcount = maxret;
@@ -3009,14 +3125,18 @@ static int dundi_lookup_internal(struct dundi_result *result, int maxret, struct
they'll get their answer anyway. */
ast_log(LOG_DEBUG, "Oooh, duplicate request for '%s@%s' for '%s'\n",
dr.number,dr.dcontext,dundi_eid_to_str(eid_str, sizeof(eid_str), &dr.root_eid));
+ close(dr.pfds[0]);
+ close(dr.pfds[1]);
return -2;
} else {
/* Wait for the cache to populate */
ast_log(LOG_DEBUG, "Waiting for similar request for '%s@%s' for '%s'\n",
dr.number,dr.dcontext,dundi_eid_to_str(eid_str, sizeof(eid_str), &pending->root_eid));
gettimeofday(&start, NULL);
- while(check_request(pending) && (calc_ms(&start) < ttlms) && (!chan || !chan->_softhangup))
+ while(check_request(pending) && (calc_ms(&start) < ttlms) && (!chan || !chan->_softhangup)) {
+ /* XXX Would be nice to have a way to poll/select here XXX */
usleep(1);
+ }
/* Continue on as normal, our cache should kick in */
}
}
@@ -3034,6 +3154,8 @@ static int dundi_lookup_internal(struct dundi_result *result, int maxret, struct
hmd->flags |= DUNDI_HINT_TTL_EXPIRED;
abort_request(&dr);
unregister_request(&dr);
+ close(dr.pfds[0]);
+ close(dr.pfds[1]);
return 0;
}
@@ -3043,14 +3165,18 @@ static int dundi_lookup_internal(struct dundi_result *result, int maxret, struct
discover_transactions(&dr);
/* Wait for transaction to come back */
gettimeofday(&start, NULL);
- while(dr.trans && (calc_ms(&start) < ttlms) && (!chan || !chan->_softhangup))
- usleep(1);
+ while(dr.trans && (calc_ms(&start) < ttlms) && (!chan || !chan->_softhangup)) {
+ ms = 100;
+ ast_waitfor_n_fd(dr.pfds, 1, &ms, NULL);
+ }
if (chan && chan->_softhangup)
ast_log(LOG_DEBUG, "Hrm, '%s' hungup before their query for %s@%s finished\n", chan->name, dr.number, dr.dcontext);
cancel_request(&dr);
unregister_request(&dr);
res = dr.respcount;
*expiration = dr.expiration;
+ close(dr.pfds[0]);
+ close(dr.pfds[1]);
return res;
}
@@ -3721,6 +3847,7 @@ static int set_config(char *config_file, struct sockaddr_in* sin)
ast_log(LOG_WARNING, "Unable to get host name!\n");
ast_mutex_lock(&peerlock);
reset_global_eid();
+ global_storehistory = 0;
strncpy(secretpath, "dundi", sizeof(secretpath) - 1);
v = ast_variable_browse(cfg, "general");
while(v) {
@@ -3798,6 +3925,8 @@ static int set_config(char *config_file, struct sockaddr_in* sin)
strncpy(email, v->value, sizeof(email) - 1);
} else if (!strcasecmp(v->name, "phone")) {
strncpy(phone, v->value, sizeof(phone) - 1);
+ } else if (!strcasecmp(v->name, "storehistory")) {
+ global_storehistory = ast_true(v->value);
}
v = v->next;
}
@@ -3832,8 +3961,10 @@ int unload_module(void)
int res;
STANDARD_HANGUP_LOCALUSERS;
ast_cli_unregister(&cli_debug);
+ ast_cli_unregister(&cli_store_history);
ast_cli_unregister(&cli_flush);
ast_cli_unregister(&cli_no_debug);
+ ast_cli_unregister(&cli_no_store_history);
ast_cli_unregister(&cli_show_peers);
ast_cli_unregister(&cli_show_entityid);
ast_cli_unregister(&cli_show_trans);
@@ -3880,8 +4011,10 @@ int load_module(void)
}
ast_cli_register(&cli_debug);
+ ast_cli_register(&cli_store_history);
ast_cli_register(&cli_flush);
ast_cli_register(&cli_no_debug);
+ ast_cli_register(&cli_no_store_history);
ast_cli_register(&cli_show_peers);
ast_cli_register(&cli_show_entityid);
ast_cli_register(&cli_show_trans);
--
GitLab