[asterisk-commits] rizzo: branch rizzo/astobj2 r47973 - /team/rizzo/astobj2/channels/chan_sip.c

asterisk-commits at lists.digium.com asterisk-commits at lists.digium.com
Thu Nov 23 13:22:27 MST 2006


Author: rizzo
Date: Thu Nov 23 14:22:26 2006
New Revision: 47973

URL: http://svn.digium.com/view/asterisk?view=rev&rev=47973
Log:
add some profiling to figure out where we are consuming time.
Not that it really belongs in a commit message, but since it is archived,
it may be interesting to see how the profiling output looks like and
what shows us:

*CLI> core show profile
profile values (13, allocated 30)
-------------------
    ID      Scale      Events        Value      Average  Name
     0: [    1000]          0            0            0  1 ms
     1: [       0]        107       166012         1551  ext_match
     2: [       0]         68      9735140       143163  sip_alloc
     3: [       0]         68      1554648        22862  sip_alloc-alloc
     4: [       0]         68      8137400       119667  sip_alloc-init
     5: [       0]        300      1358384         4527  sip_read-memset
     6: [       0]        300      3091912        10306  sip_read-recvfrom
     7: [       0]        300      2814960         9383  sip_read-parse
     8: [       0]        178     13761304        77310  sip_read-find_call
     9: [       0]        178       945952         5314  find_call-headers
    10: [       0]        178      2009652        11290  find_call-find
    11: [       0]         56     10493668       187386  find_call-tail
    12: [       0]        346       425788         1230  find_call_cb

(this is on a 2GHz box, so 2000 equals to 1 microsecond).
E.g. we see here that a lot of time is spent in the last part of find_call()
when a dialog is allocated calling sip_alloc(), and in turn, most
of the time there goes for initializing the various fields in the structure.

This is on an unloaded machine, so the cost of looking up stuff in containers
is relatively negligible, as it is the locking overhead.


Modified:
    team/rizzo/astobj2/channels/chan_sip.c

Modified: team/rizzo/astobj2/channels/chan_sip.c
URL: http://svn.digium.com/view/asterisk/team/rizzo/astobj2/channels/chan_sip.c?view=diff&rev=47973&r1=47972&r2=47973
==============================================================================
--- team/rizzo/astobj2/channels/chan_sip.c (original)
+++ team/rizzo/astobj2/channels/chan_sip.c Thu Nov 23 14:22:26 2006
@@ -4470,7 +4470,16 @@
 				 int useglobal_nat, const int intended_method)
 {
 	struct sip_pvt *p;
-
+	static int prof_id = -1, prof_alloc = -1, prof_init = -1;
+
+	if (prof_id == -1) {
+		prof_id = ast_add_profile("sip_alloc", 0);
+		prof_alloc = ast_add_profile("sip_alloc-alloc", 0);
+		prof_init = ast_add_profile("sip_alloc-init", 0);
+	}
+
+	ast_mark(prof_id, 1);
+	ast_mark(prof_alloc, 1);
 #ifdef USE_AO2
 	p = ao2_alloc(sizeof(*p), pvt_destructor);
 #else
@@ -4482,6 +4491,8 @@
 #ifndef USE_AO2
 	ast_mutex_init(&p->pvt_lock);	/* XXX not necessary in ao2 */
 #endif
+	ast_mark(prof_alloc, 0);
+	ast_mark(prof_init, 1);
 
 	/* initialize fields so that __sip_destroy() can handle them */
 	p->method = intended_method;
@@ -4592,6 +4603,8 @@
 #endif
 	if (option_debug)
 		ast_log(LOG_DEBUG, "Allocating new SIP dialog for %s - %s (%s)\n", callid ? callid : "(No Call-ID)", sip_methods[intended_method].text, p->rtp ? "With RTP" : "No RTP");
+	ast_mark(prof_init, 0);
+	ast_mark(prof_id, 0);
 	return p;
 }
 
@@ -4614,6 +4627,11 @@
 	struct find_call_cb_arg *arg = __arg;
 	/* In pedantic, we do not want packets with bad syntax to be connected to a PVT */
 	int found = FALSE;
+	static int prof_id = -1;
+	if (prof_id == -1)
+		prof_id = ast_add_profile("find_call_cb", 0);
+
+	ast_mark(prof_id, 1);
 	if (arg->method == SIP_REGISTER)
 		found = (!strcmp(p->callid, arg->callid));
 	else 
@@ -4636,6 +4654,7 @@
 		if (!found && option_debug > 4)
 			ast_log(LOG_DEBUG, "= Being pedantic: This is not our match on request: Call ID: %s Ourtag <null> Totag %s Method %s\n", p->callid, arg->totag, sip_methods[arg->method].text);
 	}
+	ast_mark(prof_id, 0);
 	return found;
 }
 
@@ -4650,10 +4669,23 @@
 	char totag[128];	/* not initialized, but not used if !pedantic */
 	char fromtag[128];	/* not initialized, but not used if !pedantic */
 	struct find_call_cb_arg arg;
-	const char *callid = get_header(req, "Call-ID");
-	const char *from = get_header(req, "From");
-	const char *to = get_header(req, "To");
-	const char *cseq = get_header(req, "Cseq");
+	const char *callid;
+	const char *from;
+	const char *to;
+	const char *cseq;
+	static int prof_head = -1, prof_find = -1, prof_tail = -1;
+	if (prof_head == -1) {
+		prof_head = ast_add_profile("find_call-headers", 0);
+		prof_find = ast_add_profile("find_call-find", 0);
+		prof_tail = ast_add_profile("find_call-tail", 0);
+	}
+
+	ast_mark(prof_head, 1);
+	callid = get_header(req, "Call-ID");
+	from = get_header(req, "From");
+	to = get_header(req, "To");
+	cseq = get_header(req, "Cseq");
+	ast_mark(prof_head, 0);
 
 	/* Call-ID, to, from and Cseq are required by RFC 3261. (Max-forwards and via too - ignored now) */
 	/* get_header always returns non-NULL so we must use ast_strlen_zero() */
@@ -4697,10 +4729,12 @@
 		}
 	}
 
+	ast_mark(prof_find, 1);
 #ifdef USE_AO2
 	p = ao2_callback(dialogs, 0 /* single, data */, find_call_cb, &arg);
 	if (p) {
 		sip_pvt_lock(p);
+		ast_mark(prof_find, 0);
 		return p;
 	}
 #else
@@ -4713,10 +4747,14 @@
 		}
 	}
 	dialoglist_unlock();
-	if (p)
+	if (p) {
+		ast_mark(prof_find, 0);
 		return p;
+	}
 #endif
+	ast_mark(prof_find, 0);
 	
+	ast_mark(prof_tail, 1);
 	/* See if the method is capable of creating a dialog */
 	if (sip_methods[intended_method].can_create == CAN_CREATE_DIALOG) {
 		if (intended_method == SIP_REFER) {
@@ -4745,6 +4783,7 @@
 					ast_log(LOG_DEBUG, "Failed allocating SIP dialog, sending 500 Server internal error and giving up\n");
 			}
 		}
+		ast_mark(prof_tail, 0);
 		return p; /* can be NULL */
 	} else if( sip_methods[intended_method].can_create == CAN_CREATE_DIALOG_UNSUPPORTED_METHOD) {
 		/* A method we do not support, let's take it on the volley */
@@ -4762,6 +4801,7 @@
 	if (option_debug > 1 && intended_method == SIP_RESPONSE)
 		ast_log(LOG_DEBUG, "That's odd...  Got a response on a call we dont know about. Callid %s\n", callid ? callid : "<unknown>");
 
+	ast_mark(prof_tail, 0);
 	return NULL;
 }
 
@@ -15207,12 +15247,13 @@
 	int recount = 0;
 	int lockretry;
 	int buflen = sizeof(req.data) - 1; /* leave an extra byte at the end for '\0' */
-	static int prof_memset = -1, prof_recv = -1, prof_parse = -1;
+	static int prof_memset = -1, prof_recv = -1, prof_parse = -1, prof_find = -1;
 
 	if (prof_memset == -1) {	/* allocate profiling counters */
 		prof_memset = ast_add_profile("sip_read-memset", 0);
 		prof_recv = ast_add_profile("sip_read-recvfrom", 0);
 		prof_parse = ast_add_profile("sip_read-parse", 0);
+		prof_find = ast_add_profile("sip_read-find_call", 0);
 	}
 	ast_mark(prof_memset, 1);
 	memset(&req, 0, sizeof(req));
@@ -15261,7 +15302,9 @@
 	/* Process request with usual deadlock avoidance */
 	for (lockretry = 100; lockretry > 0; lockretry--) {
 		/* Find the active SIP dialog or create a new one */
+		ast_mark(prof_find, 1);
 		p = find_call(&req, &sin, req.method);	/* returns p locked */
+		ast_mark(prof_find, 0);
 		if (p == NULL) {
 			if (option_debug)
 				ast_log(LOG_DEBUG, "Invalid SIP message - rejected , no callid, len %d\n", req.len);



More information about the asterisk-commits mailing list