[asterisk-commits] murf: branch murf/bug8574-1.2 r51209 - in
/team/murf/bug8574-1.2: ./ pbx/
asterisk-commits at lists.digium.com
asterisk-commits at lists.digium.com
Wed Jan 17 16:50:20 MST 2007
Author: murf
Date: Wed Jan 17 17:50:19 2007
New Revision: 51209
URL: http://svn.digium.com/view/asterisk?view=rev&rev=51209
Log:
some reloading time tracking inserted
Modified:
team/murf/bug8574-1.2/ (props changed)
team/murf/bug8574-1.2/pbx.c
team/murf/bug8574-1.2/pbx/pbx_config.c
Propchange: team/murf/bug8574-1.2/
------------------------------------------------------------------------------
automerge = Si-senor
Propchange: team/murf/bug8574-1.2/
------------------------------------------------------------------------------
automerge-email = murf at digium.com
Modified: team/murf/bug8574-1.2/pbx.c
URL: http://svn.digium.com/view/asterisk/team/murf/bug8574-1.2/pbx.c?view=diff&rev=51209&r1=51208&r2=51209
==============================================================================
--- team/murf/bug8574-1.2/pbx.c (original)
+++ team/murf/bug8574-1.2/pbx.c Wed Jan 17 17:50:19 2007
@@ -51,6 +51,7 @@
#include "asterisk/ast_expr.h"
#include "asterisk/linkedlists.h"
#include "asterisk/say.h"
+#include "asterisk/time.h"
#include "asterisk/utils.h"
#include "asterisk/causes.h"
#include "asterisk/musiconhold.h"
@@ -67,6 +68,44 @@
* of priorities, but a constant search time here would be great ;-)
*
*/
+
+int ast_tvdiff_us(struct timeval end, struct timeval start);
+struct timeval ast_tvdiff(struct timeval end, struct timeval start);
+int ast_tvdiff_us(struct timeval end, struct timeval start)
+{
+ return (end.tv_sec-start.tv_sec)*1000000 + end.tv_usec - start.tv_usec;
+}
+
+struct timeval ast_tvdiff(struct timeval end, struct timeval start)
+{
+ struct timeval d;
+ d.tv_sec = end.tv_sec - start.tv_sec;
+ d.tv_usec = end.tv_usec - start.tv_usec;
+ if (d.tv_usec < 0)
+ {
+ d.tv_usec += 1000000; /* borrow a second */
+ d.tv_sec -= 1; /* pay it back */
+ }
+ return d;
+}
+
+
+long globlock_total_holdtime =0;
+long globlock_total_sets = 0;
+long globlock_gettime = 0;
+
+long conlock_total_holdtime =0;
+long conlock_total_sets = 0;
+long conlock_gettime = 0;
+
+void log_locktime(void);
+
+void log_locktime(void)
+{
+ ast_log(LOG_NOTICE, "Total global var locked time was %ld usec to get the locks, %ld usec across %ld lock/unlock sets\n", globlock_gettime, globlock_total_holdtime, globlock_total_sets);
+ ast_log(LOG_NOTICE, "Total context locked time was %ld usec to get the locks, %ld across %ld lock/unlock sets\n", conlock_gettime, conlock_total_holdtime, conlock_total_sets);
+}
+
#ifdef LOW_MEMORY
#define EXT_DATA_SIZE 256
@@ -3651,7 +3690,7 @@
local_contexts = extcontexts;
tmp = *local_contexts;
- while(tmp) {
+ while(tmp) { /* LINEAR SEARCH FOR CONTEXT */
if (!strcasecmp(tmp->name, name)) {
ast_log(LOG_WARNING, "Tried to register context '%s', already in use\n", name);
if (!extcontexts)
@@ -3705,6 +3744,8 @@
struct ast_exten *exten;
int length;
struct ast_state_cb *thiscb, *prevcb;
+ struct timeval begin, end, diff;
+ struct timeval begin2, end2, diff2;
memset(&store, 0, sizeof(store));
AST_LIST_HEAD_INIT(&store);
@@ -3717,8 +3758,12 @@
in addition, the locks _must_ be taken in this order, because there are already
other code paths that use this order
*/
+ begin = ast_tvnow();
ast_mutex_lock(&conlock);
ast_mutex_lock(&hintlock);
+ end = ast_tvnow();
+ diff = ast_tvdiff(end, begin);
+ conlock_gettime += ((int)diff.tv_sec*1000000) + (int)diff.tv_usec;
/* preserve all watchers for hints associated with this registrar */
for (hint = hints; hint; hint = hint->next) {
@@ -3742,20 +3787,24 @@
tmp = *extcontexts;
if (registrar) {
- __ast_context_destroy(NULL,registrar);
+ begin2 = ast_tvnow();
+ __ast_context_destroy(NULL,registrar); /* destroy all system contexts with matching registrar setting */
+ end2 = ast_tvnow();
+ diff2 = ast_tvdiff(end2, begin2);
+ ast_log(LOG_NOTICE, "---time spent in context_destroy(NULL,%s) was %d.%06d sec\n", registrar, (int)diff2.tv_sec, (int)diff2.tv_usec);
while (tmp) {
lasttmp = tmp;
tmp = tmp->next;
}
} else {
while (tmp) {
- __ast_context_destroy(tmp,tmp->registrar);
+ __ast_context_destroy(tmp,tmp->registrar); /* destroy all system contexts that match the list in extcontexts */
lasttmp = tmp;
tmp = tmp->next;
}
}
if (lasttmp) {
- lasttmp->next = contexts;
+ lasttmp->next = contexts; /* add to the last context any that might remain in the system contexts */
contexts = *extcontexts;
*extcontexts = NULL;
} else
@@ -3764,10 +3813,11 @@
/* restore the watchers for hints that can be found; notify those that
cannot be restored
*/
+ begin2 = ast_tvnow();
while ((this = AST_LIST_REMOVE_HEAD(&store, list))) {
exten = ast_hint_extension(NULL, this->context, this->exten);
/* Find the hint in the list of hints */
- for (hint = hints; hint; hint = hint->next) {
+ for (hint = hints; hint; hint = hint->next) { /* LINEAR search for hints */
if (hint->exten == exten)
break;
}
@@ -3791,10 +3841,16 @@
}
free(this);
}
+ end2 = ast_tvnow();
+ diff2 = ast_tvdiff(end2, begin2);
+ ast_log(LOG_NOTICE, "---time spent in restoring hints was %d.%06d sec\n", (int)diff2.tv_sec, (int)diff2.tv_usec);
ast_mutex_unlock(&hintlock);
ast_mutex_unlock(&conlock);
-
+ end = ast_tvnow();
+ diff = ast_tvdiff(end, begin);
+ conlock_total_holdtime += ((int)diff.tv_sec*1000000) + (int)diff.tv_usec;
+ conlock_total_sets++;
return;
}
@@ -4669,6 +4725,7 @@
* priorities (same extension) are kept in a list, according to the
* peer pointer.
*/
+ struct timeval begin, end, diff;
struct ast_exten *tmp, *e, *el = NULL, *ep = NULL;
int res;
int length;
@@ -4678,13 +4735,21 @@
/* if we are adding a hint, and there are global variables, and the hint
contains variable references, then expand them
*/
+ begin = ast_tvnow();
ast_mutex_lock(&globalslock);
+ end = ast_tvnow();
+ diff = ast_tvdiff(end, begin);
+ globlock_gettime += ((int)diff.tv_sec*1000000) + (int)diff.tv_usec;
if ((priority == PRIORITY_HINT) && AST_LIST_FIRST(&globals) && strstr(application, "${")) {
pbx_substitute_variables_varshead(&globals, application, expand_buf, sizeof(expand_buf));
application = expand_buf;
}
ast_mutex_unlock(&globalslock);
-
+ end = ast_tvnow();
+ diff = ast_tvdiff(end, begin);
+ globlock_total_holdtime += ((int)diff.tv_sec*1000000) + (int)diff.tv_usec;
+ globlock_total_sets++;
+
length = sizeof(struct ast_exten);
length += strlen(extension) + 1;
length += strlen(application) + 1;
@@ -5312,6 +5377,10 @@
free(e);
}
+/* if con is set, you search the contexts for its match and remove and destroy it;
+ if it is NULL, then destroy ALL the contexts; if registrar is set, only destroy
+ contexts that have a matching registrar field. */
+
void __ast_context_destroy(struct ast_context *con, const char *registrar)
{
struct ast_context *tmp, *tmpl=NULL;
@@ -5323,7 +5392,7 @@
ast_mutex_lock(&conlock);
tmp = contexts;
while(tmp) {
- if (((tmp->name && con && con->name && !strcasecmp(tmp->name, con->name)) || !con) &&
+ if (((tmp->name && con && con->name && !strcasecmp(tmp->name, con->name)) || !con) && /* in the case of a non-null con arg, this equates to a LINEAR SEARCH for the matching context */
(!registrar || !strcasecmp(registrar, tmp->registrar))) {
/* Okay, let's lock the structure to be sure nobody else
is searching through it. */
@@ -5332,9 +5401,9 @@
return;
}
if (tmpl)
- tmpl->next = tmp->next;
+ tmpl->next = tmp->next; /* remove the matching context from the system list */
else
- contexts = tmp->next;
+ contexts = tmp->next; /* remove the first context from the system list */
/* Okay, now we're safe to let it go -- in a sense, we were
ready to let it go as soon as we locked it. */
ast_mutex_unlock(&tmp->lock);
Modified: team/murf/bug8574-1.2/pbx/pbx_config.c
URL: http://svn.digium.com/view/asterisk/team/murf/bug8574-1.2/pbx/pbx_config.c?view=diff&rev=51209&r1=51208&r2=51209
==============================================================================
--- team/murf/bug8574-1.2/pbx/pbx_config.c (original)
+++ team/murf/bug8574-1.2/pbx/pbx_config.c Wed Jan 17 17:50:19 2007
@@ -39,6 +39,7 @@
#include "asterisk/options.h"
#include "asterisk/module.h"
#include "asterisk/logger.h"
+#include "asterisk/time.h"
#include "asterisk/cli.h"
#include "asterisk/callerid.h"
@@ -116,6 +117,31 @@
" clearglobalvars is set to yes in extensions.conf\n"
"\n"
"Example: extensions reload\n";
+
+
+/* some time diff funcs for mini-profiling */
+
+static int ast_tvdiff_us(struct timeval end, struct timeval start);
+static struct timeval ast_tvdiff(struct timeval end, struct timeval start);
+
+static int ast_tvdiff_us(struct timeval end, struct timeval start)
+{
+ return (end.tv_sec-start.tv_sec)*1000000 + end.tv_usec - start.tv_usec;
+}
+
+static struct timeval ast_tvdiff(struct timeval end, struct timeval start)
+{
+ struct timeval d;
+ d.tv_sec = end.tv_sec - start.tv_sec;
+ d.tv_usec = end.tv_usec - start.tv_usec;
+ if (d.tv_usec < 0)
+ {
+ d.tv_usec += 1000000; /* borrow a second */
+ d.tv_sec -= 1; /* pay it back */
+ }
+ return d;
+}
+
/*
* Implementation of functions provided by this module
@@ -1428,11 +1454,18 @@
}
static int pbx_load_module(void);
+void log_locktime(void);
static int handle_reload_extensions(int fd, int argc, char *argv[])
{
+ struct timeval begin, end, diff;
+ begin = ast_tvnow();
if (argc!=2) return RESULT_SHOWUSAGE;
pbx_load_module();
+ end = ast_tvnow();
+ diff = ast_tvdiff(end, begin);
+ ast_log(LOG_NOTICE, "Total Reload time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+ log_locktime();
return RESULT_SUCCESS;
}
@@ -1623,9 +1656,15 @@
char *label;
char realvalue[256];
int lastpri = -2;
-
+ struct timeval begin, endt, diff;
+
+ begin = ast_tvnow();
cfg = ast_config_load(config);
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "Total extensions.conf Read time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
if (cfg) {
+ begin = ast_tvnow();
/* Use existing config to populate the PBX table */
static_config = ast_true(ast_variable_retrieve(cfg, "general",
"static"));
@@ -1645,6 +1684,10 @@
pbx_builtin_setvar_helper(NULL, v->name, realvalue);
v = v->next;
}
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "global var set time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+ begin = ast_tvnow();
cxt = ast_category_browse(cfg, NULL);
while(cxt) {
/* All categories but "general" or "globals" are considered contexts */
@@ -1652,7 +1695,7 @@
cxt = ast_category_browse(cfg, cxt);
continue;
}
- if ((con=ast_context_create(&local_contexts,cxt, registrar))) {
+ if ((con=ast_context_create(&local_contexts,cxt, registrar))) { /* local contexts is empty on first invocation */
v = ast_variable_browse(cfg, cxt);
while(v) {
if (!strcasecmp(v->name, "exten")) {
@@ -1782,7 +1825,10 @@
data = "";
if (ast_context_add_switch2(con, appl, data, !strcasecmp(v->name, "eswitch"), registrar))
ast_log(LOG_WARNING, "Unable to include switch '%s' in context '%s'\n", v->value, cxt);
+ } else {
+ ast_log(LOG_WARNING,"Unrecognized directive '%s' in context '%s' -- ignoring.\n", v->name, cxt);
}
+
v = v->next;
}
}
@@ -1790,13 +1836,29 @@
}
ast_config_destroy(cfg);
}
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "Conversion to internal dialplan format time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+
+ begin = ast_tvnow();
ast_merge_contexts_and_delete(&local_contexts,registrar);
-
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "merge/delete time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+
+ begin = ast_tvnow();
for (con = ast_walk_contexts(NULL); con; con = ast_walk_contexts(con))
ast_context_verify_includes(con);
-
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "verify_include time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+
+ begin = ast_tvnow();
pbx_set_autofallthrough(autofallthrough_config);
-
+ endt = ast_tvnow();
+ diff = ast_tvdiff(endt, begin);
+ ast_log(LOG_NOTICE, "set autofallthru time was %d.%06d sec\n", (int)diff.tv_sec, (int)diff.tv_usec);
+
return 0;
}
More information about the asterisk-commits
mailing list