Hopefully, this will resolve the issues that russellb had with this log_show_lock().
authorSteve Murphy <murf@digium.com>
Tue, 22 Apr 2008 14:38:46 +0000 (14:38 +0000)
committerSteve Murphy <murf@digium.com>
Tue, 22 Apr 2008 14:38:46 +0000 (14:38 +0000)
I gathered the code that filled the string, and put it in a different func which
I cryptically call "append_lock_information()".
Now, both log_show_lock(), and handle_show_locks() both call this code to do
the work. Tested, seems to work fine.
Also, log_show_lock was modified to use the ast_str stuff, along with checking
for successful ast_str creation, and freeing the ast_str obj when finished.
A break was inserted to terminate the search for the lock; we should never
see it twice.

An example usage in chan_sip.c was created as a comment, for instructional
purposes.

git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@114520 65c4cc65-6c06-0410-ace0-fbb531ad65f3

channels/chan_sip.c
main/utils.c

index 31bd576..391970b 100644 (file)
@@ -12927,8 +12927,10 @@ static int dialog_needdestroy(void *dialogobj, void *arg, int flags)
        struct sip_pvt *dialog = dialogobj;
        time_t *t = arg;
        
+       /* log_show_lock(ao2_object_get_lockaddr(dialog)); this is an example of how to use log_show_lock() */
        if (sip_pvt_trylock(dialog)) {
-               /* this path gets executed fairly frequently (3% or so) even in low load
+               /* In very short-duration calls via sipp,
+                  this path gets executed fairly frequently (3% or so) even in low load
                   situations; the routines we most commonly fight for a lock with:
                   sip_answer (7 out of 9)
                   sip_hangup (2 out of 9)
index 3ae7d09..a91e106 100644 (file)
@@ -714,52 +714,86 @@ static const char *locktype2str(enum ast_lock_type type)
        return "UNKNOWN";
 }
 
-/*! \todo this function is very broken and duplicates a lot of code ... */
+static void append_lock_information(struct ast_str **str, struct thr_lock_info *lock_info, int i)
+{
+       int j;
+       ast_mutex_t *lock;
+       
+       ast_str_append(str, 0, "=== ---> %sLock #%d (%s): %s %d %s %s %p (%d)\n", 
+                                  lock_info->locks[i].pending > 0 ? "Waiting for " : 
+                                  lock_info->locks[i].pending < 0 ? "Tried and failed to get " : "", i,
+                                  lock_info->locks[i].file, 
+                                  locktype2str(lock_info->locks[i].type),
+                                  lock_info->locks[i].line_num,
+                                  lock_info->locks[i].func, lock_info->locks[i].lock_name,
+                                  lock_info->locks[i].lock_addr, 
+                                  lock_info->locks[i].times_locked);
+       
+       if (!lock_info->locks[i].pending || lock_info->locks[i].pending == -1)
+               return;
+       
+       /* We only have further details for mutexes right now */
+       if (lock_info->locks[i].type != AST_MUTEX)
+               return;
+       
+       lock = lock_info->locks[i].lock_addr;
+       
+       ast_reentrancy_lock(lock);
+       for (j = 0; *str && j < lock->reentrancy; j++) {
+               ast_str_append(str, 0, "=== --- ---> Locked Here: %s line %d (%s)\n",
+                                          lock->file[j], lock->lineno[j], lock->func[j]);
+       }
+       ast_reentrancy_unlock(lock);    
+}
+
+
+/*! This function can help you find highly temporal locks; locks that happen for a 
+    short time, but at unexpected times, usually at times that create a deadlock,
+       Why is this thing locked right then? Who is locking it? Who am I fighting
+    with for this lock? 
+
+       To answer such questions, just call this routine before you would normally try
+       to aquire a lock. It doesn't do anything if the lock is not acquired. If the
+       lock is taken, it will publish a line or two to the console via ast_log().
+
+       Sometimes, the lock message is pretty uninformative. For instance, you might
+       find that the lock is being aquired deep within the astobj2 code; this tells
+       you little about higher level routines that call the astobj2 routines.
+       But, using gdb, you can set a break at the ast_log below, and for that
+       breakpoint, you can set the commands:
+         where
+         cont
+       which will give a stack trace and continue. -- that aught to do the job!
+
+*/
 void log_show_lock(void *this_lock_addr)
 {
        struct thr_lock_info *lock_info;
-       struct ast_str *str = NULL;
+       struct ast_str *str;
+
+       if (!(str = ast_str_create(4096))) {
+               ast_log(LOG_NOTICE,"Could not create str\n");
+               return;
+       }
+       
 
        pthread_mutex_lock(&lock_infos_lock.mutex);
        AST_LIST_TRAVERSE(&lock_infos, lock_info, entry) {
                int i;
                pthread_mutex_lock(&lock_info->lock);
                for (i = 0; str && i < lock_info->num_locks; i++) {
-                       int j;
-                       ast_mutex_t *lock;
+                       /* ONLY show info about this particular lock, if
+                          it's acquired... */
                        if (lock_info->locks[i].lock_addr == this_lock_addr) {
-                               
-                               ast_log(LOG_NOTICE, "---> %sLock #%d (%s): %s %d %s %s %p (%d)\n", 
-                                               lock_info->locks[i].pending > 0 ? "Waiting for " : lock_info->locks[i].pending < 0 ? "Tried and failed to get " : "", 
-                                               i,
-                                               lock_info->locks[i].file, 
-                                               locktype2str(lock_info->locks[i].type),
-                                               lock_info->locks[i].line_num,
-                                               lock_info->locks[i].func, 
-                                               lock_info->locks[i].lock_name,
-                                               lock_info->locks[i].lock_addr, 
-                                               lock_info->locks[i].times_locked);
-                               
-                               if (!lock_info->locks[i].pending || lock_info->locks[i].pending == -1)
-                                       continue;
-                               
-                               /* We only have further details for mutexes right now */
-                               if (lock_info->locks[i].type != AST_MUTEX)
-                                       continue;
-                               
-                               lock = lock_info->locks[i].lock_addr;
-                               
-                               ast_reentrancy_lock(lock);
-                               for (j = 0; str && j < lock->reentrancy; j++) {
-                                       ast_log(LOG_NOTICE, "--- ---> Locked Here: %s line %d (%s)\n",
-                                                                  lock->file[j], lock->lineno[j], lock->func[j]);
-                               }
-                               ast_reentrancy_unlock(lock);    
+                               append_lock_information(&str, lock_info, i);
+                               ast_log(LOG_NOTICE, "%s", str->str);
+                               break;
                        }
                }
                pthread_mutex_unlock(&lock_info->lock);
        }
        pthread_mutex_unlock(&lock_infos_lock.mutex);
+       ast_free(str);
 }
 
 
@@ -802,34 +836,7 @@ static char *handle_show_locks(struct ast_cli_entry *e, int cmd, struct ast_cli_
                        lock_info->thread_name);
                pthread_mutex_lock(&lock_info->lock);
                for (i = 0; str && i < lock_info->num_locks; i++) {
-                       int j;
-                       ast_mutex_t *lock;
-
-                       ast_str_append(&str, 0, "=== ---> %sLock #%d (%s): %s %d %s %s %p (%d)\n", 
-                               lock_info->locks[i].pending > 0 ? "Waiting for " : 
-                                       lock_info->locks[i].pending < 0 ? "Tried and failed to get " : "", i,
-                               lock_info->locks[i].file, 
-                               locktype2str(lock_info->locks[i].type),
-                               lock_info->locks[i].line_num,
-                               lock_info->locks[i].func, lock_info->locks[i].lock_name,
-                               lock_info->locks[i].lock_addr, 
-                               lock_info->locks[i].times_locked);
-
-                       if (!lock_info->locks[i].pending || lock_info->locks[i].pending == -1)
-                               continue;
-
-                       /* We only have further details for mutexes right now */
-                       if (lock_info->locks[i].type != AST_MUTEX)
-                               continue;
-
-                       lock = lock_info->locks[i].lock_addr;
-
-                       ast_reentrancy_lock(lock);
-                       for (j = 0; str && j < lock->reentrancy; j++) {
-                               ast_str_append(&str, 0, "=== --- ---> Locked Here: %s line %d (%s)\n",
-                                       lock->file[j], lock->lineno[j], lock->func[j]);
-                       }
-                       ast_reentrancy_unlock(lock);    
+                       append_lock_information(&str, lock_info, i);
                }
                pthread_mutex_unlock(&lock_info->lock);
                if (!str)