[asterisk-commits] murf: branch murf/mtxprof r126114 - in /team/murf/mtxprof: ./ channels/ inclu...

SVN commits to the Asterisk project asterisk-commits at lists.digium.com
Fri Jun 27 18:11:40 CDT 2008


Author: murf
Date: Fri Jun 27 18:11:39 2008
New Revision: 126114

URL: http://svn.digium.com/view/asterisk?view=rev&rev=126114
Log:
Todays little experiments added. Cut down some of the output from the device_state calls using channel_find_locked(), just report the 199-failures msg instead.

Modified:
    team/murf/mtxprof/Makefile
    team/murf/mtxprof/channels/chan_sip.c
    team/murf/mtxprof/include/asterisk/lock.h
    team/murf/mtxprof/main/channel.c
    team/murf/mtxprof/main/pbx.c
    team/murf/mtxprof/main/utils.c

Modified: team/murf/mtxprof/Makefile
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/Makefile?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/Makefile (original)
+++ team/murf/mtxprof/Makefile Fri Jun 27 18:11:39 2008
@@ -116,8 +116,8 @@
 OVERWRITE=y
 
 # Include debug and macro symbols in the executables (-g) and profiling info (-pg)
-DEBUG=-g3
-
+DEBUG=-g3 -pg
+ASTLDFLAGS += -pg
 
 # Define standard directories for various platforms
 # These apply if they are not redefined in asterisk.conf 

Modified: team/murf/mtxprof/channels/chan_sip.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/channels/chan_sip.c?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/channels/chan_sip.c (original)
+++ team/murf/mtxprof/channels/chan_sip.c Fri Jun 27 18:11:39 2008
@@ -1176,7 +1176,11 @@
 };
 
 
-
+/*! this array will store the invocation counts for the 10 
+ funcs that the sched facility initiates. To see if one is
+ going nuts */
+
+int sched_invocation_counts[10] = {0};
 
 /*! \brief sip_pvt: structures used for each SIP dialog, ie. a call, a registration, a subscribe.
  * Created and initialized by sip_alloc(), the descriptor goes into the list of
@@ -2920,6 +2924,7 @@
 	int reschedule = DEFAULT_RETRANS;
 	int xmitres = 0;
 	
+	sched_invocation_counts[0]++;
 	/* Lock channel PVT */
 	sip_pvt_lock(pkt->owner);
 
@@ -3119,6 +3124,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *)data;
 
+	sched_invocation_counts[1]++;
 	/* If this is a subscription, tell the phone that we got a timeout */
 	if (p->subscribed) {
 		transmit_state_notify(p, AST_EXTENSION_DEACTIVATED, 1, TRUE);	/* Send last notification */
@@ -4452,6 +4458,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *)arg;
 
+	sched_invocation_counts[3]++;
 	sip_pvt_lock(p);
 	p->initid = -1;	/* event gone, will not be rescheduled */
 	if (p->owner) {
@@ -4804,6 +4811,7 @@
 		ast_log(LOG_ERROR, "update_call_counter(%s, %d) called with no event!\n", name, event);
 	}
 	if (p) {
+		ast_log(LOG_NOTICE,"device state changed called from here 1\n");
 		ast_device_state_changed("SIP/%s", p->name);
 		unref_peer(p, "update_call_counter: unref_peer from call counter");
 	} else /* u must be set */
@@ -9647,6 +9655,7 @@
 	/* if we are here, we know that we need to reregister. */
 	struct sip_registry *r= (struct sip_registry *) data;
 
+	sched_invocation_counts[7]++;
 	/* if we couldn't get a reference to the registry object, punt */
 	if (!r)
 		return 0;
@@ -9687,6 +9696,7 @@
 	struct sip_pvt *p;
 	int res;
 
+	sched_invocation_counts[4]++;
 	/* if we couldn't get a reference to the registry object, punt */
 	if (!r)
 		return 0;
@@ -10154,6 +10164,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 	
+	sched_invocation_counts[2]++;
 	if (!peer)		/* Hmmm. We have no peer. Weird. */
 		return 0;
 
@@ -10164,6 +10175,7 @@
 	
 	manager_event(EVENT_FLAG_SYSTEM, "PeerStatus", "ChannelType: SIP\r\nPeer: SIP/%s\r\nPeerStatus: Unregistered\r\nCause: Expired\r\n", peer->name);
 	register_peer_exten(peer, FALSE);	/* Remove regexten */
+	ast_log(LOG_NOTICE,"device state changed called from here 2\n");
 	ast_device_state_changed("SIP/%s", peer->name);
 
 	/* Do we need to release this peer from memory? 
@@ -10189,6 +10201,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 
+	sched_invocation_counts[5]++;
 	peer->pokeexpire = -1;
 	sip_poke_peer(peer, 0);
 	return 0;
@@ -10786,6 +10799,7 @@
 	ast_atomic_fetchadd_int(&peer->onHold, (hold ? +1 : -1));
 
 	/* Request device state update */
+	ast_log(LOG_NOTICE,"device state changed called from here 3\n");
 	ast_device_state_changed("SIP/%s", peer->name);
 	unref_peer(peer, "sip_peer_hold: from find_peer operation");
 	
@@ -11037,6 +11051,7 @@
 		}
 	}
 	if (!res) {
+		ast_log(LOG_NOTICE,"device state changed called from here 4\n");
 		ast_device_state_changed("SIP/%s", peer->name);
 	}
 	if (res < 0) {
@@ -13944,6 +13959,8 @@
 static char *sip_show_sched(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
 {
 	char cbuf[2256];
+	int i;
+	
 	struct ast_cb_names cbnames = {9, { "retrans_pkt",
                                         "__sip_autodestruct",
                                         "expire_register",
@@ -13976,6 +13993,14 @@
 	ast_cli(a->fd, "\n");
 	ast_sched_report(sched, cbuf, sizeof(cbuf), &cbnames);
 	ast_cli(a->fd, "%s", cbuf);
+
+	ast_cli(a->fd, "Invocation counts:\n");
+	for(i=0; i<9; i++) {
+		char buf2[200];
+		sprintf(buf2,"%s : %d\n", cbnames.list[i], sched_invocation_counts[i]);
+		ast_cli(a->fd, "%s", buf2);
+	}
+	
 	return CLI_SUCCESS;
 }
 
@@ -15804,6 +15829,7 @@
 {
 	struct sip_pvt *p = (struct sip_pvt *) data;
 
+	sched_invocation_counts[8]++;
 	ast_set_flag(&p->flags[0], SIP_NEEDREINVITE);	
 	p->waitid = -1;
 	dialog_unref(p, "unref the dialog ptr from sip_reinvite_retry, because it held a dialog ptr");
@@ -19985,14 +20011,17 @@
 	}
 	if (monitor_thread != AST_PTHREADT_NULL) {
 		/* Wake up the thread */
+		ast_log(LOG_NOTICE,"Waking SIP monitor thread\n");
 		pthread_kill(monitor_thread, SIGURG);
 	} else {
 		/* Start a new monitor */
+		ast_log(LOG_NOTICE,"Creating SIP monitor background thread\n");
 		if (ast_pthread_create_background(&monitor_thread, NULL, do_monitor, NULL) < 0) {
 			ast_mutex_unlock(&monlock);
 			ast_log(LOG_ERROR, "Unable to start monitor thread.\n");
 			return -1;
 		}
+		ast_log(LOG_NOTICE,"SIP monitor background thread Created\n");
 	}
 	ast_mutex_unlock(&monlock);
 	return 0;
@@ -20339,6 +20368,7 @@
 {
 	struct sip_peer *peer = (struct sip_peer *)data;
 	
+	sched_invocation_counts[6]++;
 	peer->pokeexpire = -1;
 	if (peer->lastms > -1) {
 		ast_log(LOG_NOTICE, "Peer '%s' is now UNREACHABLE!  Last qualify: %d\n", peer->name, peer->lastms);
@@ -20353,6 +20383,7 @@
 	}
 	
 	peer->lastms = -1;
+	ast_log(LOG_NOTICE,"device state changed called from here 5\n");
 	ast_device_state_changed("SIP/%s", peer->name);
 	/* Try again quickly */
 	AST_SCHED_REPLACE(peer->pokeexpire, sched, 
@@ -23017,7 +23048,7 @@
 /*! \brief PBX load module - initialization */
 static int load_module(void)
 {
-	ast_verbose("SIP channel loading...\n");
+	ast_log(LOG_NOTICE,"SIP channel loading...\n");
 	/* the fact that ao2_containers can't resize automatically is a major worry! */
     /* if the number of objects gets above MAX_XXX_BUCKETS, things will slow down */
 	users = ao2_t_container_alloc(hash_user_size, user_hash_cb, user_cmp_cb, "allocate users");
@@ -23104,7 +23135,7 @@
 		"regserver", RQ_CHAR, 20,
 		"useragent", RQ_CHAR, 20,
 		SENTINEL);
-
+	ast_log(LOG_NOTICE,"SIP CHANNEL Finished Load\n");
 	return AST_MODULE_LOAD_SUCCESS;
 }
 

Modified: team/murf/mtxprof/include/asterisk/lock.h
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/include/asterisk/lock.h?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/include/asterisk/lock.h (original)
+++ team/murf/mtxprof/include/asterisk/lock.h Fri Jun 27 18:11:39 2008
@@ -1791,8 +1791,9 @@
 #define ast_channel_unlock_comma(x)		ast_log(LOG_NOTICE,"UnLockChan %s\n", x->name), ast_mutex_unlock(&x->lock_dont_use)
 /*! \brief Try locking a channel. If DEBUG_CHANNEL_LOCKS is defined 
 	in the Makefile, print relevant output for debugging */
-#define ast_channel_trylock(x)		ast_log(LOG_NOTICE,"TryChan %s\n", x->name); ast_mutex_trylock(&x->lock_dont_use)
-#define ast_channel_trylock_assign(x, var)		ast_log(LOG_NOTICE,"TryChan %s\n", x->name); var = ast_mutex_trylock(&x->lock_dont_use)
+#define ast_channel_trylock(x)		if(!ast_mutex_trylock(&x->lock_dont_use))ast_log(LOG_NOTICE,"TryLockChan for %s success\n", x->name)
+#define ast_channel_trylock_assign(x, var)		var = ast_mutex_trylock(&x->lock_dont_use);	\
+	if(!var)ast_log(LOG_NOTICE,"TryChan %s success\n", x->name); 
 #else
 
 #define ast_channel_lock(a) __ast_channel_lock(a, __FILE__, __LINE__, __PRETTY_FUNCTION__)

Modified: team/murf/mtxprof/main/channel.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/channel.c?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/main/channel.c (original)
+++ team/murf/mtxprof/main/channel.c Fri Jun 27 18:11:39 2008
@@ -1159,7 +1159,6 @@
 		/* exit if chan not found or mutex acquired successfully */
 		/* this is slightly unsafe, as we _should_ hold the lock to access c->name */
 		if (c) {
-			ast_log(LOG_NOTICE,"prev=%p; name=%s, len=%d; context=%s; exten=%s\n", prev, name, namelen, context, exten);
 			ast_channel_trylock_assign(c,lockret);
 		}
 			
@@ -1170,6 +1169,7 @@
 				/* We are about to fail due to a deadlock, so report this
 				 * while we still have the list lock.
 				 */
+				ast_log(LOG_NOTICE, "Failure, could not lock '%p' after %d retries!\n", c, retries);
 				ast_debug(1, "Failure, could not lock '%p' after %d retries!\n", c, retries);
 				/* As we have deadlocked, we will skip this channel and
 				 * see if there is another match.

Modified: team/murf/mtxprof/main/pbx.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/pbx.c?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/main/pbx.c (original)
+++ team/murf/mtxprof/main/pbx.c Fri Jun 27 18:11:39 2008
@@ -3798,7 +3798,8 @@
 	   PBX has finished running on the channel
 	 */
 	struct ast_channel *c = data;
-
+	usleep(1);
+	
 	__ast_pbx_run(c);
 	decrease_call_count();
 

Modified: team/murf/mtxprof/main/utils.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/utils.c?view=diff&rev=126114&r1=126113&r2=126114
==============================================================================
--- team/murf/mtxprof/main/utils.c (original)
+++ team/murf/mtxprof/main/utils.c Fri Jun 27 18:11:39 2008
@@ -1041,6 +1041,11 @@
 			     void *data, size_t stacksize, const char *file, const char *caller,
 			     int line, const char *start_fn)
 {
+	struct timeval start9, end9;
+	static int totaltime = 0;
+	static int numtimes = 0;
+	int timediff, ret7;
+	
 #if !defined(LOW_MEMORY)
 	struct thr_arg *a;
 #endif
@@ -1079,7 +1084,16 @@
 	}
 #endif /* !LOW_MEMORY */
 
-	return pthread_create(thread, attr, start_routine, data); /* We're in ast_pthread_create, so it's okay */
+	start9 = ast_tvnow();
+	ret7 =  pthread_create(thread, attr, start_routine, data); /* We're in ast_pthread_create, so it's okay */
+	end9 = ast_tvnow();
+	timediff = ast_tvdiff_us(end9, start9);
+	totaltime += timediff;
+	numtimes++;
+	
+	ast_log(LOG_NOTICE,"pthread_create took %d microseconds, avg=%d usec (%d times)\n", timediff, totaltime/numtimes, numtimes);
+
+	return ret7;
 }
 
 




More information about the asterisk-commits mailing list