[asterisk-commits] murf: branch murf/mtxprof r128115 - in /team/murf/mtxprof: channels/ funcs/ i...

SVN commits to the Asterisk project asterisk-commits at lists.digium.com
Fri Jul 4 12:44:00 CDT 2008


Author: murf
Date: Fri Jul  4 12:43:59 2008
New Revision: 128115

URL: http://svn.digium.com/view/asterisk?view=rev&rev=128115
Log:
Added to profiling a set of fields that record who has the lock if a lock, or trylock can't get it right away. And I also added unlock events to the profile, where the time recorded is the number of cpu ticks that the lock was held. This is with MTX_PROFILE set and DEBUG_THREADS set.

Modified:
    team/murf/mtxprof/channels/chan_sip.c
    team/murf/mtxprof/funcs/func_channel.c
    team/murf/mtxprof/funcs/func_lock.c
    team/murf/mtxprof/include/asterisk.h
    team/murf/mtxprof/include/asterisk/lock.h
    team/murf/mtxprof/main/asterisk.c
    team/murf/mtxprof/main/astobj2.c
    team/murf/mtxprof/main/channel.c
    team/murf/mtxprof/main/pbx.c
    team/murf/mtxprof/main/utils.c
    team/murf/mtxprof/res/res_smdi.c
    team/murf/mtxprof/utils/hashtest.c
    team/murf/mtxprof/utils/hashtest2.c
    team/murf/mtxprof/utils/refcounter.c

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=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/channels/chan_sip.c (original)
+++ team/murf/mtxprof/channels/chan_sip.c Fri Jul  4 12:43:59 2008
@@ -17996,30 +17996,25 @@
 			if (strcmp(p->exten, ast_pickup_ext())) {	/* Call to extension -start pbx on this call */
 				static int pbx_mark = -1;
 				enum ast_pbx_result res;
-#ifdef HAVE_MTX_PROFILE
 				struct timeval start9, end9;
 				static int totaltime = 0;
 				static int numtimes = 0;
 				int timediff;
 				uint64_t st1;
-#endif
 				
 				if (pbx_mark == -1) {
 					pbx_mark = ast_add_profile("pbx_start_time", 0);
 				}
-#ifdef HAVE_MTX_PROFILE
-				ast_log(LOG_NOTICE,"about to start PBX\n");
 				start9 = ast_tvnow();
 				st1 = ast_mark2();
-#endif
 				res = ast_pbx_start(c);
-#ifdef HAVE_MTX_PROFILE
 				ast_mark3(pbx_mark, st1);
 				end9 = ast_tvnow();
 				timediff = ast_tvdiff_us(end9, start9);
 				totaltime += timediff;
 				numtimes++;
 				
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 				ast_log(LOG_NOTICE,"PBX is started -- took %d microseconds, avg=%d usec (%d times)\n", timediff, totaltime/numtimes, numtimes);
 #endif
 				switch(res) {
@@ -19559,6 +19554,7 @@
 	int recount = 0;
 	int nounlock = 0;
 	int lockretry;
+	int trylocked = 0;
 
 	if (sip_debug_test_addr(sin))	/* Set the debug flag early on packet level */
 		req->debug = 1;
@@ -19605,6 +19601,8 @@
 		if (p->owner) {
 			ast_channel_trylock_assign(p->owner,lockret);
 		}
+		if (p->owner && !lockret)
+			trylocked = 1;
 		if (!p->owner || !lockret)
 			break;	/* locking succeeded */
 		ast_debug(1, "Failed to grab owner channel lock, trying again. (SIP call %s)\n", p->callid);
@@ -19640,11 +19638,9 @@
 		
 	if (recount)
 		ast_update_use_count();
-#ifdef EXPERIMENT_TO_NOT_UNLOCK_IF_NOT_LOCKED
-	if (p->owner && !nounlock) {
+	if (p->owner && !nounlock && trylocked) {
 		ast_channel_unlock(p->owner);
 	}
-#endif
 	sip_pvt_unlock(p);
 	ast_mutex_unlock(&netlock);
 	ao2_t_ref(p, -1, "throw away dialog ptr from find_call at end of routine"); /* p is gone after the return */

Modified: team/murf/mtxprof/funcs/func_channel.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/funcs/func_channel.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/funcs/func_channel.c (original)
+++ team/murf/mtxprof/funcs/func_channel.c Fri Jul  4 12:43:59 2008
@@ -263,7 +263,7 @@
 		}
 	}
 
-	for (c = ast_channel_walk_locked(NULL); c; ast_channel_unlock_comma(c), c = ast_channel_walk_locked(c)) {
+	for (c = ast_channel_walk_locked(NULL); c; c = ast_channel_walk_locked(c)) {
 		if (ast_strlen_zero(data) || regexec(&re, c->name, 0, NULL, 0) == 0) {
 			size_t namelen = strlen(c->name);
 			if (buflen + namelen + (ast_strlen_zero(buf) ? 0 : 1) + 1 < maxlen) {
@@ -277,6 +277,7 @@
 				ast_log(LOG_WARNING, "Number of channels exceeds the available buffer space.  Output will be truncated!\n");
 			}
 		}
+		ast_channel_unlock(c);
 	}
 
 	if (!ast_strlen_zero(data)) {

Modified: team/murf/mtxprof/funcs/func_lock.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/funcs/func_lock.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/funcs/func_lock.c (original)
+++ team/murf/mtxprof/funcs/func_lock.c Fri Jul  4 12:43:59 2008
@@ -183,7 +183,7 @@
 		struct timeval start = ast_tvnow();
 		for (;;) {
 			int tlock;
-			ast_mutex_trylock_assign(&current->mutex, tlock)
+			ast_mutex_trylock_assign(&current->mutex, tlock);
 			if ((res = tlock) == 0)
 				break;
 			if (ast_tvdiff_ms(ast_tvnow(), start) > 3000)

Modified: team/murf/mtxprof/include/asterisk.h
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/include/asterisk.h?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/include/asterisk.h (original)
+++ team/murf/mtxprof/include/asterisk.h Fri Jul  4 12:43:59 2008
@@ -157,8 +157,7 @@
 uint64_t ast_mark2(void);
 void ast_mark3(int mtx_ind, uint64_t start);
 void ast_mtxprof_bumpbusy(int mtx_ind);
-void ast_mtxprof_busywith(int mtx_ind, int x);
-
+void ast_mtxprof_set_ext_data(int mtx_ind, const char *file, int lineno, const char *func, const char *name, int reent);
 #else /* LOW_MEMORY */
 #define ast_add_profile(a, b) 0
 #define ast_profile(a, b) do { } while (0)

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=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/include/asterisk/lock.h (original)
+++ team/murf/mtxprof/include/asterisk/lock.h Fri Jul  4 12:43:59 2008
@@ -122,10 +122,10 @@
 #include <errno.h>
 
 #ifdef HAVE_BKTR
-#define AST_LOCK_TRACK_INIT_VALUE { { NULL }, { 0 }, 0, { NULL }, { 0 }, {{{ 0 }}}, PTHREAD_MUTEX_INIT_VALUE }
-
-#else
-#define AST_LOCK_TRACK_INIT_VALUE { { NULL }, { 0 }, 0, { NULL }, { 0 }, PTHREAD_MUTEX_INIT_VALUE }
+#define AST_LOCK_TRACK_INIT_VALUE { { NULL }, { 0 }, 0, { NULL }, { 0 }, {{{ 0 }}}, 0, PTHREAD_MUTEX_INIT_VALUE }
+
+#else
+#define AST_LOCK_TRACK_INIT_VALUE { { NULL }, { 0 }, 0, { NULL }, { 0 }, 0, PTHREAD_MUTEX_INIT_VALUE }
 #endif
 
 #define AST_MUTEX_INIT_VALUE { AST_LOCK_TRACK_INIT_VALUE, 1, PTHREAD_MUTEX_INIT_VALUE }
@@ -144,6 +144,7 @@
 #ifdef HAVE_BKTR
 	struct ast_bt backtrace[AST_MAX_REENTRANCY];
 #endif
+	uint64_t time_locked;
 	pthread_mutex_t reentr_mutex;
 };
 
@@ -554,23 +555,24 @@
 	do {
 		if (*(mtx_prof) == -1) {
 			char nbuf[512];
-			snprintf(nbuf, sizeof(nbuf), "%s__%s__%d__%s", file, func, lineno, lockstr);
+			snprintf(nbuf, sizeof(nbuf), "%s__%s__%d__%s", filename, func, lineno, mutex_name);
 			*(mtx_prof) = ast_add_profile(nbuf, 0);
 		}
 		*(start) = ast_mark2();
 		res = pthread_mutex_trylock(&t->mutex);
-		if (i) {
-			if (i == EBUSY) {
+		if (res) {
+			if (res == EBUSY) {
 				/* record who we are waiting on! */
 				ast_mtxprof_bumpbusy(*(mtx_prof));
+				if (t->tracking)
+					ast_mtxprof_set_ext_data(*(mtx_prof), t->track.file[0], t->track.lineno[0], t->track.func[0], mutex_name, t->track.reentrancy);
 			} else {
-				ast_log(LOG_WARNING,"trying of lock yields %d\n", i);
+				ast_log(LOG_WARNING,"trying of lock yields %d\n", res);
 			}
 			res = pthread_mutex_lock(&t->mutex);
 		}
 		ast_mark3(*(mtx_prof), *(start));
-		return i;
-	} while (0)
+	} while (0);
 #else /* NOT DETECT_DEADLOCKS and NOT HAVE_MTX_PROFILE */
 		res = pthread_mutex_lock(&t->mutex);
 #endif /* HAVE_MTX_PROFILE */
@@ -590,6 +592,7 @@
 		}
 		ast_reentrancy_unlock(lt);
 		if (t->tracking) {
+			t->track.time_locked = ast_mark2();
 			ast_mark_lock_acquired(&t->mutex);
 		}
 	} else {
@@ -618,7 +621,7 @@
 }
 
 static inline int __ast_pthread_mutex_trylock(const char *filename, int lineno, const char *func,
-                                              const char* mutex_name, ast_mutex_t *t)
+                                              const char* mutex_name, ast_mutex_t *t, int *mtx_prof, uint64_t *start )
 {
 	int res;
 	struct ast_lock_track *lt= &t->track;
@@ -654,7 +657,18 @@
 #endif
 	}
 
+#ifdef	HAVE_MTX_PROFILE
+	if (*(mtx_prof) == -1) {
+		char nbuf[512];
+		snprintf(nbuf, sizeof(nbuf), "%s__%s__%d__%s", filename, func, lineno, mutex_name);
+		*(mtx_prof) = ast_add_profile(nbuf, 0);
+	}
+	*start = ast_mark2();
+#endif
 	if (!(res = pthread_mutex_trylock(&t->mutex))) {
+#ifdef	HAVE_MTX_PROFILE
+		ast_mark3(*(mtx_prof), *(start));
+#endif
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy < AST_MAX_REENTRANCY) {
 			lt->file[lt->reentrancy] = filename;
@@ -669,16 +683,28 @@
 		ast_reentrancy_unlock(lt);
 		if (t->tracking) {
 			ast_mark_lock_acquired(&t->mutex);
-		}
-	} else if (t->tracking) {
-		ast_mark_lock_failed(&t->mutex);
-	}
-
+			t->track.time_locked = ast_mark2();
+		}
+	} else {
+#ifdef	HAVE_MTX_PROFILE
+			if (res == EBUSY) {
+				/* record who we are waiting on! */
+				ast_mtxprof_bumpbusy(*(mtx_prof));
+				if (t->tracking)
+					ast_mtxprof_set_ext_data(*(mtx_prof), t->track.file[0], t->track.lineno[0], t->track.func[0], mutex_name, t->track.reentrancy);
+			} else {
+				ast_log(LOG_WARNING,"trying of lock yields %d\n", res);
+			}
+#endif
+		if (t->tracking) {
+			ast_mark_lock_failed(&t->mutex);
+		}
+	}
 	return res;
 }
 
 static inline int __ast_pthread_mutex_unlock(const char *filename, int lineno, const char *func,
-					     const char *mutex_name, ast_mutex_t *t)
+ const char *mutex_name, ast_mutex_t *t, int *mtx_prof)
 {
 	int res;
 	struct ast_lock_track *lt = &t->track;
@@ -732,7 +758,17 @@
 #endif
 	ast_reentrancy_unlock(lt);
 
+#ifdef	HAVE_MTX_PROFILE
 	if (t->tracking) {
+		if (*(mtx_prof) == -1) {
+			char nbuf[512];
+			snprintf(nbuf, sizeof(nbuf), "UNLOCK:%s__%s__%d__%s", filename, func, lineno, mutex_name);
+			*(mtx_prof) = ast_add_profile(nbuf, 0);
+		}
+		ast_mtxprof_set_ext_data(*(mtx_prof), t->track.file[0], t->track.lineno[0], t->track.func[0], mutex_name, t->track.reentrancy);
+		ast_mark3(*(mtx_prof), t->track.time_locked);
+#endif
+	
 #ifdef HAVE_BKTR
 		ast_remove_lock_info(&t->mutex, bt);
 #else
@@ -971,15 +1007,18 @@
 #define ast_mutex_lock(a)			do {uint64_t start; static int mutprof=-1; __ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof, &start);} while(0)
 #define ast_mutex_lock_assign(a,retval) do {uint64_t start; static int mutprof=-1; retval = __ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof, &start);} while(0)
 #define ast_mutex_trylock(a)			do {uint64_t start; static int mutprof=-1; __ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof, &start);} while(0)
-#define ast_mutex_trylock_assign(a,retval)			{uint64_t start; static int mutprof=-1; retval=__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof, &start);} while(0)
+#define ast_mutex_trylock_assign(a,retval)			do {uint64_t start; static int mutprof=-1; retval=__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof, &start);} while(0)
+#define ast_mutex_unlock(a)			do {static int mutprof=-1; __ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof);} while(0)
+#define ast_mutex_unlock_assign(a,retval)			do {static int mutprof=-1; retval=__ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof);} while(0)
 #else
 #define ast_mutex_lock(a)			__ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, 0, 0)
 #define ast_mutex_lock_assign(a,retval) retval = __ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, 0, 0)
-#define ast_mutex_trylock(a)			__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
-#define ast_mutex_trylock_assign(a,retval)			retval=__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
+#define ast_mutex_trylock(a)			__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, 0, 0)
+#define ast_mutex_trylock_assign(a,retval)			retval=__ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, 0, 0)
+#define ast_mutex_unlock(a)			__ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, 0)
+#define ast_mutex_unlock_assign(a,retval)			retval=__ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a, &mutprof)
 #endif
 #define ast_mutex_destroy(a)			__ast_pthread_mutex_destroy(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
-#define ast_mutex_unlock(a)			__ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
 #define ast_cond_init(cond, attr)		__ast_cond_init(__FILE__, __LINE__, __PRETTY_FUNCTION__, #cond, cond, attr)
 #define ast_cond_destroy(cond)			__ast_cond_destroy(__FILE__, __LINE__, __PRETTY_FUNCTION__, #cond, cond)
 #define ast_cond_signal(cond)			__ast_cond_signal(__FILE__, __LINE__, __PRETTY_FUNCTION__, #cond, cond)
@@ -1701,15 +1740,14 @@
  * and destructors to create/destroy global mutexes.
  */
 #define __AST_MUTEX_DEFINE(scope, mutex, init_val, track)	\
-	scope ast_mutex_t mutex = init_val;			\
+	scope ast_mutex_t mutex = init_val;			              \
 static void  __attribute__ ((constructor)) init_##mutex(void)	\
 {								\
 	if (track)						\
 		ast_mutex_init(&mutex);				\
 	else							\
 		ast_mutex_init_notracking(&mutex);		\
-}								\
-								\
+} \
 static void  __attribute__ ((destructor)) fini_##mutex(void)	\
 {								\
 	ast_mutex_destroy(&mutex);				\
@@ -1864,7 +1902,7 @@
 #ifndef DEBUG_CHANNEL_LOCKS
 /*! \brief Lock a channel. If DEBUG_CHANNEL_LOCKS is defined 
 	in the Makefile, print relevant output for debugging */
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 #define ast_channel_lock(x)		ast_log(LOG_NOTICE,"LockChan %s\n", x->name); ast_mutex_lock(&x->lock_dont_use); \
 	ast_log(LOG_NOTICE,"LockChan %s OBTAINED\n", x->name);
 /*! \brief Unlock a channel. If DEBUG_CHANNEL_LOCKS is defined 

Modified: team/murf/mtxprof/main/asterisk.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/asterisk.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/main/asterisk.c (original)
+++ team/murf/mtxprof/main/asterisk.c Fri Jul  4 12:43:59 2008
@@ -522,6 +522,11 @@
 	int	value;
 	int	events;
 	int busycount;
+	const char *ext_file;
+	int         ext_lineno;
+	const char *ext_func;
+	const char *ext_name;
+	int         ext_reent;
 };
 
 struct profile_data {
@@ -562,6 +567,11 @@
 	prof_data->e[n].busycount = 0;
 	prof_data->e[n].mark = 0;
 	prof_data->e[n].scale = scale;
+	prof_data->e[n].ext_file = 0;
+	prof_data->e[n].ext_lineno = 0;
+	prof_data->e[n].ext_func = 0;
+	prof_data->e[n].ext_name = 0;
+	prof_data->e[n].ext_reent = 0;
 	return n;
 }
 
@@ -635,8 +645,13 @@
 	ast_atomic_fetchadd_int(&prof_data->e[mtx_ind].busycount, 1);
 }
 
-void ast_mtxprof_busywith(int mtx_ind, int x)
-{
+void ast_mtxprof_set_ext_data(int mtx_ind, const char *file, int lineno, const char *func, const char *name, int reent)
+{
+	prof_data->e[mtx_ind].ext_file = file;
+	prof_data->e[mtx_ind].ext_lineno = lineno;
+	prof_data->e[mtx_ind].ext_func = func;
+	prof_data->e[mtx_ind].ext_name = name;
+	prof_data->e[mtx_ind].ext_reent = reent;
 }
 
 #define DEFINE_PROFILE_MIN_MAX_VALUES min = 0; \
@@ -672,17 +687,26 @@
 	DEFINE_PROFILE_MIN_MAX_VALUES;
 	ast_cli(a->fd, "profile values (%d, allocated %d)\n-------------------\n",
 		prof_data->entries, prof_data->max_size);
-	ast_cli(a->fd, "%6s   %8s  %10s %10s %12s %12s  %s\n", "ID", "Scale", "Events", "BusyCnt",
-			"Value", "Average", "Name");
+	ast_cli(a->fd, "%6s   %8s  %10s %10s %12s %12s  %s (%s)\n", "ID", "Scale", "Events", "BusyCnt",
+			"Value", "Average", "Name", "Lock From");
 	for (i = min; i < max; i++) {
 		struct profile_entry *e = &prof_data->e[i];
-		if (!search || strstr(prof_data->e[i].name, search))
-		    ast_cli(a->fd, "%6d: [%8ld] %10ld %10ld %12lld %12lld  %s\n",
-			i,
-			(long)e->scale,
-			(long)e->events, (long)e->busycount, (long long)e->value,
-			(long long)(e->events ? e->value / e->events : e->value),
-			e->name);
+		if (!search || strstr(prof_data->e[i].name, search)) {
+			if (prof_data->e[i].ext_file)
+				ast_cli(a->fd, "%6d: [%8ld] %10ld %10ld %12lld %12lld  %s (%s:%d:%s:%s[%d])\n",
+						i,
+						(long)e->scale,
+						(long)e->events, (long)e->busycount, (long long)e->value,
+						(long long)(e->events ? e->value / e->events : e->value),
+						e->name, e->ext_file, e->ext_lineno, e->ext_func, e->ext_name, e->ext_reent);
+			else
+				ast_cli(a->fd, "%6d: [%8ld] %10ld %10ld %12lld %12lld  %s\n",
+						i,
+						(long)e->scale,
+						(long)e->events, (long)e->busycount, (long long)e->value,
+						(long long)(e->events ? e->value / e->events : e->value),
+						e->name);
+		}
 	}
 	return CLI_SUCCESS;
 }

Modified: team/murf/mtxprof/main/astobj2.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/astobj2.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/main/astobj2.c (original)
+++ team/murf/mtxprof/main/astobj2.c Fri Jul  4 12:43:59 2008
@@ -157,6 +157,7 @@
 
 int ao2_unlock(void *user_data)
 {
+	int ret;
 	struct astobj2 *p = INTERNAL_OBJ(user_data);
 
 	if (p == NULL)
@@ -166,7 +167,8 @@
 	ast_atomic_fetchadd_int(&ao2.total_locked, -1);
 #endif
 
-	return ast_mutex_unlock(&p->priv_data.lock);
+	ast_mutex_unlock_assign(&p->priv_data.lock, ret);
+	return ret;
 }
 
 int ao2_trylock(void *user_data)

Modified: team/murf/mtxprof/main/channel.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/channel.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/main/channel.c (original)
+++ team/murf/mtxprof/main/channel.c Fri Jul  4 12:43:59 2008
@@ -1170,9 +1170,12 @@
 				 * while we still have the list lock.
 				 */
 #ifdef HAVE_MTX_PROFILE
-				ast_log(LOG_NOTICE, "Failure, could not lock '%p' after %d retries!\n", c, retries);
+				ast_log(LOG_NOTICE, "Failure, could not lock '%p' after %d retries (%d)!\n", &c->lock_dont_use, retries, lockret);
 #endif
-				ast_debug(1, "Failure, could not lock '%p' after %d retries!\n", c, retries);
+				if (c)
+					log_show_lock(&c->lock_dont_use);
+				
+				ast_debug(1, "Failure, could not lock '%p' after %d retries (%d)!\n", c, retries, lockret);
 				/* As we have deadlocked, we will skip this channel and
 				 * see if there is another match.
 				 * NOTE: No point doing this for a full-name match,
@@ -1688,15 +1691,13 @@
 {
 	int res = 0;
 
-#ifdef DEBUG_THREADS
+#ifdef DEBUG_THREADS_NOT
 	
 	static int callcount = 0;
-	if (!((callcount++)%200)) {
+	if (!((callcount++)%                                                                                                                                                                    200)) {
 		ast_log(LOG_ERROR,"callcount is %d, channel is %s (%p)\n", callcount, chan->name, chan);
-		
-		log_show_lock(&chan->lock_dont_use);
-	}
-	
+	}
+	log_show_lock(&chan->lock_dont_use);
 #endif
 	
 	ast_channel_lock(chan); /* in sip runs, this lock eats up a tremendous amount of time */
@@ -1704,11 +1705,11 @@
 	/* You can't answer an outbound call */
 	if (ast_test_flag(chan, AST_FLAG_OUTGOING)) {
 		ast_channel_unlock(chan);
-		return 0;
-	}
-
+		return 0;                
+	}
+  
 	/* Stop if we're a zombie or need a soft hangup */
-	if (ast_test_flag(chan, AST_FLAG_ZOMBIE) || ast_check_hangup(chan)) {
+	if (ast_test_flag(chan, AST_FLAG_ZOMBIE) || ast_check_hangup(chan)) {   
 		ast_channel_unlock(chan);
 		return -1;
 	}

Modified: team/murf/mtxprof/main/pbx.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/pbx.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/main/pbx.c (original)
+++ team/murf/mtxprof/main/pbx.c Fri Jul  4 12:43:59 2008
@@ -3795,7 +3795,7 @@
 enum ast_pbx_result ast_pbx_start(struct ast_channel *c)
 {
 	pthread_t t;
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 	struct timeval start9 = ast_tvnow(), end9;
 	static int totaltime = 0;
 	static int numtimes = 0;
@@ -3813,7 +3813,7 @@
 	if (increase_call_count(c))
 		return AST_PBX_CALL_LIMIT;
 
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 	end9 = ast_tvnow();
 	timediff = ast_tvdiff_us(end9, start9);
 	totaltime += timediff;
@@ -4271,7 +4271,7 @@
 
 	/* if we found context, unlock macrolock */
 	if (ret == 0) 
-		ret = ast_mutex_unlock(&c->macrolock);
+		ast_mutex_unlock_assign(&c->macrolock,ret);
 
 	return ret;
 }

Modified: team/murf/mtxprof/main/utils.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/main/utils.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/main/utils.c (original)
+++ team/murf/mtxprof/main/utils.c Fri Jul  4 12:43:59 2008
@@ -513,7 +513,7 @@
 #ifdef DEBUG_THREADS
 
 /*! \brief A reasonable maximum number of locks a thread would be holding ... */
-#define AST_MAX_LOCKS 64
+#define AST_MAX_LOCKS 128
 
 /* Allow direct use of pthread_mutex_t and friends */
 #undef pthread_mutex_t
@@ -865,6 +865,7 @@
 void log_show_lock(void *this_lock_addr)
 {
 	struct thr_lock_info *lock_info;
+	ast_mutex_t *lockptr = this_lock_addr;
 	struct ast_str *str;
 	int lockinfos = 0;
 	int totlocks = 0;
@@ -873,6 +874,8 @@
 		ast_log(LOG_NOTICE,"Could not create str\n");
 		return;
 	}
+	ast_log(LOG_ERROR,"lockptr:tracking=%d;\n", lockptr->tracking);
+	ast_log(LOG_ERROR,"file:%s; lineno:%d; func:%s; re-ent:%d\n",lockptr->track.file[0], lockptr->track.lineno[0], lockptr->track.func[0], lockptr->track.reentrancy);
 	
 	ast_log(LOG_ERROR,"Look for lock addr %p in list\n", this_lock_addr);
 	pthread_mutex_lock(&lock_infos_lock.mutex);
@@ -884,7 +887,7 @@
 			/* ONLY show info about this particular lock, if
 			   it's acquired... */
 			totlocks++;
-			/*	if (lock_info->locks[i].lock_addr == this_lock_addr) */ {
+			/* if (lock_info->locks[i].lock_addr == this_lock_addr)*/ {
 				ast_str_reset(str);
 				ast_str_append(&str, 0, "Thread ID: %d (%s)\n", (int)lock_info->thread_id, lock_info->thread_name);
 				append_lock_information(&str, lock_info, i);
@@ -904,7 +907,9 @@
 {
 	struct thr_lock_info *lock_info;
 	struct ast_str *str;
-
+	int threadcount = 0;
+	int lockcount = 0;
+	
 	if (!(str = ast_str_create(4096)))
 		return CLI_FAILURE;
 
@@ -935,11 +940,13 @@
 	pthread_mutex_lock(&lock_infos_lock.mutex);
 	AST_LIST_TRAVERSE(&lock_infos, lock_info, entry) {
 		int i;
+		threadcount++;
 		if (lock_info->num_locks) {
 			ast_str_append(&str, 0, "=== Thread ID: %d (%s)\n", (int) lock_info->thread_id,
 				lock_info->thread_name);
 			pthread_mutex_lock(&lock_info->lock);
 			for (i = 0; str && i < lock_info->num_locks; i++) {
+				lockcount++;
 				append_lock_information(&str, lock_info, i);
 			}
 			pthread_mutex_unlock(&lock_info->lock);
@@ -964,6 +971,7 @@
 
 	ast_cli(a->fd, "%s", str->str);
 
+	ast_cli(a->fd, "=== Total Threads=%d; Locks=%d\n", threadcount, lockcount);
 	ast_free(str);
 
 	return CLI_SUCCESS;
@@ -1041,7 +1049,7 @@
 			     void *data, size_t stacksize, const char *file, const char *caller,
 			     int line, const char *start_fn)
 {
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 	struct timeval start9, end9;
 	static int totaltime = 0;
 	static int numtimes = 0;
@@ -1097,11 +1105,11 @@
 	}
 #endif
 
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 	start9 = ast_tvnow();
 #endif
 	ret7 =  pthread_create(thread, attr, start_routine, data); /* We're in ast_pthread_create, so it's okay */
-#ifdef HAVE_MTX_PROFILE
+#ifdef HAVE_MTX_PROFILE_NOT_NOW
 	end9 = ast_tvnow();
 	timediff = ast_tvdiff_us(end9, start9);
 	totaltime += timediff;

Modified: team/murf/mtxprof/res/res_smdi.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/res/res_smdi.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/res/res_smdi.c (original)
+++ team/murf/mtxprof/res/res_smdi.c Fri Jul  4 12:43:59 2008
@@ -265,11 +265,14 @@
 
 static inline int unlock_msg_q(struct ast_smdi_interface *iface, enum smdi_message_type type)
 {
+	int res;
 	switch (type) {
 	case SMDI_MWI:
-		return ast_mutex_unlock(&iface->mwi_q_lock);
+		ast_mutex_unlock_assign(&iface->mwi_q_lock,res);
+		return res;
 	case SMDI_MD:
-		return ast_mutex_unlock(&iface->md_q_lock);
+		ast_mutex_unlock_assign(&iface->md_q_lock,res);
+		return res;
 	}
 
 	return -1;

Modified: team/murf/mtxprof/utils/hashtest.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/utils/hashtest.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/utils/hashtest.c (original)
+++ team/murf/mtxprof/utils/hashtest.c Fri Jul  4 12:43:59 2008
@@ -51,7 +51,7 @@
 uint64_t ast_mark2(void){ return 0;}
 void ast_mark3(int mtx_ind, uint64_t start) {}
 void ast_mtxprof_bumpbusy(int mtx_ind){}
-
+void ast_mtxprof_set_ext_data(int mtx_ind, const char *file, int lineno, const char *func, const char *name, int reent) {}
 #endif
 
 struct ht_element 

Modified: team/murf/mtxprof/utils/hashtest2.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/utils/hashtest2.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/utils/hashtest2.c (original)
+++ team/murf/mtxprof/utils/hashtest2.c Fri Jul  4 12:43:59 2008
@@ -53,6 +53,7 @@
 uint64_t ast_mark2(void){ return 0;}
 void ast_mark3(int mtx_ind, uint64_t start) {}
 void ast_mtxprof_bumpbusy(int mtx_ind) {}
+void ast_mtxprof_set_ext_data(int mtx_ind, const char *file, int lineno, const char *func, const char *name, int reent) {}
 #endif
 
 /* my OBJECT */

Modified: team/murf/mtxprof/utils/refcounter.c
URL: http://svn.digium.com/view/asterisk/team/murf/mtxprof/utils/refcounter.c?view=diff&rev=128115&r1=128114&r2=128115
==============================================================================
--- team/murf/mtxprof/utils/refcounter.c (original)
+++ team/murf/mtxprof/utils/refcounter.c Fri Jul  4 12:43:59 2008
@@ -240,7 +240,7 @@
 uint64_t ast_mark2(void){ return 0;}
 void ast_mark3(int mtx_ind, uint64_t start) {}
 void ast_mtxprof_bumpbusy(int mtx_ind) {}
-
+void ast_mtxprof_set_ext_data(int mtx_ind, const char *file, int lineno, const char *func, const char *name, int reent) {}
 #endif
 
 void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)




More information about the asterisk-commits mailing list