astobj2: Record lock usage to refs log when DEBUG_THREADS is enabled.

When DEBUG_THREADS is enabled we can know if the astobj2 mutex / rwlock
was ever used, so it can be recorded in the REF_DEBUG destructor entry.

Create contrib/scripts/reflocks.py to process locking used by
allocator.  This can be used to identify places where
AO2_ALLOC_OPT_LOCK_NOLOCK should be used to reduce memory usage.

Change-Id: I2e3cd23336a97df2692b545f548fd79b14b53bf4

contrib/scripts/refcounter.py

@@ -108,6 +108,10 @@ def process_file(options):
             else:
                 current_objects[obj]['curcount'] += int(parsed_line['delta'])
 
+            if 'destructor' in parsed_line['state']:
+                # refcounter.py doesn't care about lock-state.
+                parsed_line['state'] = '**destructor**'
+
             current_objects[obj]['log'].append(
                 "[%s] %s:%s %s: %s %s - [%s]" % (
                     parsed_line['thread_id'],

contrib/scripts/reflocks.py

@@ -0,0 +1,126 @@
+#!/usr/bin/env python
+"""Process a ref debug log for lock usage
+
+ This file will process a log file created by Asterisk
+ that was compiled with REF_DEBUG and DEBUG_THREADS.
+
+ See http://www.asterisk.org for more information about
+ the Asterisk project. Please do not directly contact
+ any of the maintainers of this project for assistance;
+ the project provides a web site, mailing lists and IRC
+ channels for your use.
+
+ This program is free software, distributed under the terms of
+ the GNU General Public License Version 2. See the LICENSE file
+ at the top of the source tree.
+
+ Copyright (C) 2018, CFWare, LLC
+ Corey Farrell <git@cfware.com>
+"""
+
+from __future__ import print_function
+import sys
+import os
+
+from optparse import OptionParser
+
+
+def process_file(options):
+    """The routine that kicks off processing a ref file"""
+
+    object_types = {}
+    objects = {}
+    filename = options.filepath
+
+    with open(filename, 'r') as ref_file:
+        for line in ref_file:
+            if 'constructor' not in line and 'destructor' not in line:
+                continue
+            # The line format is:
+            # addr,delta,thread_id,file,line,function,state,tag
+            # Only addr, file, line, function, state are used by reflocks.py
+            tokens = line.strip().split(',', 7)
+            addr = tokens[0]
+            state = tokens[6]
+            if 'constructor' in state:
+                obj_type = '%s:%s:%s' % (tokens[3], tokens[4], tokens[5])
+                if obj_type not in object_types:
+                    object_types[obj_type] = {
+                        'used': 0,
+                        'unused': 0,
+                        'lockobj': 0,
+                        'none': 0
+                    }
+                objects[addr] = obj_type
+            elif 'destructor' in state:
+                if addr not in objects:
+                    # This error would be reported by refcounter.py.
+                    continue
+                obj_type = objects[addr]
+                del objects[addr]
+                if '**lock-state:unused**' in state:
+                    object_types[obj_type]['unused'] += 1
+                elif '**lock-state:used**' in state:
+                    object_types[obj_type]['used'] += 1
+                elif '**lock-state:lockobj**' in state:
+                    object_types[obj_type]['lockobj'] += 1
+                elif '**lock-state:none**' in state:
+                    object_types[obj_type]['none'] += 1
+
+    for (allocator, info) in object_types.items():
+        stats = [];
+        if info['used'] > 0:
+            if not options.used:
+                continue
+            stats.append("%d used" % info['used'])
+        if info['unused'] > 0:
+            stats.append("%d unused" % info['unused'])
+        if info['lockobj'] > 0 and options.lockobj:
+            stats.append("%d lockobj" % info['lockobj'])
+        if info['none'] > 0 and options.none:
+            stats.append("%d none" % info['none'])
+        if len(stats) == 0:
+            continue
+        print("%s: %s" % (allocator, ', '.join(stats)))
+
+
+def main(argv=None):
+    """Main entry point for the script"""
+
+    ret_code = 0
+
+    if argv is None:
+        argv = sys.argv
+
+    parser = OptionParser()
+
+    parser.add_option("-f", "--file", action="store", type="string",
+                      dest="filepath", default="/var/log/asterisk/refs",
+                      help="The full path to the refs file to process")
+    parser.add_option("-u", "--suppress-used", action="store_false",
+                      dest="used", default=True,
+                      help="Don't output types that have used locks.")
+    parser.add_option("-n", "--show-none", action="store_true",
+                      dest="none", default=False,
+                      help="Show counts of objects with no locking.")
+    parser.add_option("-o", "--show-lockobj", action="store_true",
+                      dest="lockobj", default=False,
+                      help="Show counts of objects with a lockobj.")
+
+    (options, args) = parser.parse_args(argv)
+
+    if not os.path.isfile(options.filepath):
+        print("File not found: %s" % options.filepath, file=sys.stderr)
+        return -1
+
+    try:
+        process_file(options)
+    except (KeyboardInterrupt, SystemExit, IOError):
+        print("File processing cancelled", file=sys.stderr)
+        return -1
+
+    return ret_code
+
+
+if __name__ == "__main__":
+    sys.exit(main(sys.argv))

main/astobj2.c

@@ -473,6 +473,9 @@ int __ao2_ref(void *user_data, int delta,
 	int32_t current_value;
 	int32_t ret;
 	struct ao2_weakproxy *weakproxy = NULL;
+#ifdef DEBUG_THREADS
+	const char *lock_state;
+#endif
 
 	if (obj == NULL) {
 		if (ref_log && user_data) {
@@ -592,21 +595,33 @@ int __ao2_ref(void *user_data, int delta,
 	switch (obj->priv_data.options & AO2_ALLOC_OPT_LOCK_MASK) {
 	case AO2_ALLOC_OPT_LOCK_MUTEX:
 		obj_mutex = INTERNAL_OBJ_MUTEX(user_data);
+#ifdef DEBUG_THREADS
+		lock_state = obj_mutex->mutex.lock.flags.setup ? "used" : "unused";
+#endif
 		ast_mutex_destroy(&obj_mutex->mutex.lock);
 
 		ast_free(obj_mutex);
 		break;
 	case AO2_ALLOC_OPT_LOCK_RWLOCK:
 		obj_rwlock = INTERNAL_OBJ_RWLOCK(user_data);
+#ifdef DEBUG_THREADS
+		lock_state = obj_rwlock->rwlock.lock.flags.setup ? "used" : "unused";
+#endif
 		ast_rwlock_destroy(&obj_rwlock->rwlock.lock);
 
 		ast_free(obj_rwlock);
 		break;
 	case AO2_ALLOC_OPT_LOCK_NOLOCK:
+#ifdef DEBUG_THREADS
+		lock_state = "none";
+#endif
 		ast_free(obj);
 		break;
 	case AO2_ALLOC_OPT_LOCK_OBJ:
 		obj_lockobj = INTERNAL_OBJ_LOCKOBJ(user_data);
+#ifdef DEBUG_THREADS
+		lock_state = "lockobj";
+#endif
 		ao2_t_ref(obj_lockobj->lockobj.lock, -1, "release lockobj");
 
 		ast_free(obj_lockobj);
@@ -614,12 +629,22 @@ int __ao2_ref(void *user_data, int delta,
 	default:
 		ast_log(__LOG_ERROR, file, line, func,
 			"Invalid lock option on ao2 object %p\n", user_data);
+#ifdef DEBUG_THREADS
+		lock_state = "invalid";
+#endif
 		break;
 	}
 
 	if (ref_log && tag) {
-		fprintf(ref_log, "%p,%d,%d,%s,%d,%s,**destructor**,%s\n",
+		fprintf(ref_log, "%p,%d,%d,%s,%d,%s,**destructor%s%s**,%s\n",
-			user_data, delta, ast_get_tid(), file, line, func, tag);
+			user_data, delta, ast_get_tid(), file, line, func,
+#ifdef DEBUG_THREADS
+			"**lock-state:",
+			lock_state,
+#else
+			"", "",
+#endif
+			tag);
 		fflush(ref_log);
 	}