refdebug: Create refstats.py script.

This allows us to process AO2 statistics for total objects, memory usage, memory overhead and lock usage. * Install refstats.py and reflocks.py into the Asterisk scripts folder. * Enable support for reflocks.py without DEBUG_THREADS. Steal a bit from the ao2 magic to flag when an object lock is used. Remove 'lockobj' from reflocks.py since we can now record 'used' or 'unused' for those objects. Add comments to explain thread safety of the 'struct __priv_data' bitfields. Change-Id: I84e9d679cc86d772cc97c888d9d856a17e0d3a4a
2018-10-10 05:37:23 -04:00 · 2018-10-10 05:37:23 -04:00 · 79677ead28
parent 5ff42a2bb5
commit 79677ead28
5 changed files with 243 additions and 47 deletions
--- a/contrib/Makefile
+++ b/contrib/Makefile
@ -25,9 +25,13 @@ install:
 	$(INSTALL) -m 755 scripts/ast_loggrabber "$(DESTDIR)$(ASTDATADIR)/scripts/ast_loggrabber"
 	$(INSTALL) -m 755 scripts/ast_coredumper "$(DESTDIR)$(ASTDATADIR)/scripts/ast_coredumper"
 	$(INSTALL) -m 755 scripts/refcounter.py "$(DESTDIR)$(ASTDATADIR)/scripts/refcounter.py"
+	$(INSTALL) -m 755 scripts/refstats.py "$(DESTDIR)$(ASTDATADIR)/scripts/refstats.py"
+	$(INSTALL) -m 755 scripts/reflocks.py "$(DESTDIR)$(ASTDATADIR)/scripts/reflocks.py"

 uninstall:
 	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/ast_logescalator"
 	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/ast_loggrabber"
 	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/ast_coredumper"
 	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/refcounter.py"
+	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/refstats.py"
+	-rm -f "$(DESTDIR)$(ASTDATADIR)/scripts/reflocks.py"
--- a/contrib/scripts/refcounter.py
+++ b/contrib/scripts/refcounter.py
@ -108,8 +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.
+            # Suppress object sizes and lock-state from output logs.
+            if 'constructor' in parsed_line['state']:
+                parsed_line['state'] = '**constructor**'
+            elif 'destructor' in parsed_line['state']:
                parsed_line['state'] = '**destructor**'

            current_objects[obj]['log'].append(
--- a/contrib/scripts/reflocks.py
+++ b/contrib/scripts/reflocks.py
@ -48,7 +48,6 @@ def process_file(options):
                    object_types[obj_type] = {
                        'used': 0,
                        'unused': 0,
-                        'lockobj': 0,
                        'none': 0
                    }
                objects[addr] = obj_type
@ -62,8 +61,6 @@ def process_file(options):
                    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

@ -75,8 +72,6 @@ def process_file(options):
            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:
@ -103,9 +98,6 @@ def main(argv=None):
    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)

--- a/contrib/scripts/refstats.py
+++ b/contrib/scripts/refstats.py
@ -0,0 +1,180 @@
+#!/usr/bin/env python
+"""Process a ref debug log for memory usage
+
+ This will provide information about total and peak
+ allocations.
+
+ 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 create_stats():
+    """Create statistics object"""
+    return {
+        'count': 0,
+        'overhead': 0,
+        'user_data': 0,
+        'totalmem': 0
+    }
+
+
+def update_stats(current, peak, total, key, direction, delta):
+    """Update statistics objects"""
+
+    if direction == 1:
+        total[key] += delta
+
+    delta *= direction
+    current[key] += delta
+    if current[key] > peak[key]:
+        peak[key] = current[key]
+
+
+def process_file(options):
+    """The routine that kicks off processing a ref file"""
+
+    current = create_stats()
+    total = create_stats()
+    peak = create_stats()
+    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:
+                split_state = state.split("**")
+                if len(split_state) < 4:
+                    print("File does not contain object size information", file=sys.stderr)
+                    sys.exit(1)
+
+                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,
+                        'none': 0
+                    }
+                overhead = int(split_state[2])
+                user_data = int(split_state[3])
+                obj = objects[addr] = {
+                    'overhead': overhead,
+                    'user_data': user_data,
+                    'obj_type': obj_type
+                }
+
+                direction = 1
+            else:
+                if addr not in objects:
+                    # This error would be reported by refcounter.py.
+                    continue
+                obj = objects[addr]
+                del objects[addr]
+                direction = -1
+                obj_type = obj['obj_type']
+                if '**lock-state:unused**' in state:
+                    object_types[obj_type]['unused'] += 1
+                elif '**lock-state:used**' in state:
+                    object_types[obj_type]['used'] += 1
+
+            # Increment current and peak usage
+            update_stats(current, peak, total, 'count', direction, 1)
+            update_stats(current, peak, total, 'overhead', direction, obj['overhead'])
+            update_stats(current, peak, total, 'user_data', direction, obj['user_data'])
+            update_stats(current, peak, total, 'totalmem', direction, obj['overhead'] + obj['user_data'])
+
+    print("Total usage statistics:")
+    print("%20s: %d" % ("Count", total['count']))
+    print("%20s: %d" % ("Total Memory (k)", total['totalmem'] / 1024))
+    print("%20s: %d (%.2f%%)" % ("Overhead (k)", total['overhead'] / 1024, total['overhead'] * 100.0 / total['totalmem']))
+    print("%20s: %d" % ("User Data (k)", total['user_data'] / 1024))
+    print("")
+    print("Peak usage statistics:")
+    print("%20s: %d" % ("Count", peak['count']))
+    print("%20s: %d" % ("Total Memory (k)", peak['totalmem'] / 1024))
+    print("%20s: %d (%.2f%%)" % ("Overhead (k)", peak['overhead'] / 1024, peak['overhead'] * 100.0 / peak['totalmem']))
+    print("%20s: %d" % ("User Data (k)", peak['user_data'] / 1024))
+    print("")
+
+    lockbyobj = {'used': 0, 'total': 0}
+    lockbytype = {'used': 0, 'total': 0}
+    for (allocator, info) in object_types.items():
+        lockbyobj['used'] += info['used']
+        lockbyobj['total'] += info['used'] + info['unused']
+
+        if info['used'] != 0:
+            lockbytype['used'] += 1
+        elif info['unused'] == 0:
+            # This object type doesn't have locking.
+            continue
+        lockbytype['total'] += 1
+
+    print("Lock usage statistics:")
+    print("%20s: %d of %d used (%.2f%%)" % (
+        "By object",
+        lockbyobj['used'],
+        lockbyobj['total'],
+        lockbyobj['used'] * 100.0 / lockbyobj['total']))
+    print("%20s: %d of %d used (%.2f%%)" % (
+        "By type",
+        lockbytype['used'],
+        lockbytype['total'],
+        lockbytype['used'] * 100.0 / lockbytype['total']))
+
+
+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")
+
+    (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))
--- a/main/astobj2.c
+++ b/main/astobj2.c
@ -61,15 +61,40 @@ struct __priv_data {
 #endif
 	/*! Number of references held for this object */
 	int32_t ref_counter;
-	/*! The ao2 object option flags */
+	/*!
+	 * \brief The ao2 object option flags.
+	 *
+	 * \note This field is constant after object creation.  It shares
+	 *       a uint32_t with \ref lockused and \ref magic.
+	 */
 	uint32_t options:2;
-	/*! magic number.  This is used to verify that a pointer passed in is a
-	 *  valid astobj2 or ao2_weak reference */
-	uint32_t magic:30;
+	/*!
+	 * \brief Set to 1 when the lock is used if refdebug is enabled.
+	 *
+	 * \note This bit-field may be modified after object creation.  It
+	 *       shares a uint32_t with \ref options and \ref magic.
+	 */
+	uint32_t lockused:1;
+	/*!
+	 * \brief Magic number.
+	 *
+	 * This is used to verify that a pointer is a valid astobj2 or ao2_weak
+	 * reference.
+	 *
+	 * \note This field is constant after object creation.  It shares
+	 *       a uint32_t with \ref options and \ref lockused.
+	 *
+	 * \warning Stealing bits for any additional writable fields would cause
+	 *          reentrancy issues if using bitfields.  If any additional
+	 *          writable bits are required in the future we will need to put
+	 *          all bitfields into a single 'uint32_t flags' field and use
+	 *          atomic operations from \file lock.h to perform writes.
+	 */
+	uint32_t magic:29;
 };

-#define	AO2_MAGIC	0x3a70b123
-#define	AO2_WEAK	0x3a70b122
+#define	AO2_MAGIC	0x1a70b123
+#define	AO2_WEAK	0x1a70b122
 #define IS_AO2_MAGIC_BAD(p) (AO2_MAGIC != (p->priv_data.magic | 1))

 /*!
@ -206,6 +231,10 @@ int __ao2_lock(void *user_data, enum ao2_lock_req lock_how, const char *file, co
 		return -1;
 	}

+	if (ref_log) {
+		obj->priv_data.lockused  = 1;
+	}
+
 	switch (obj->priv_data.options & AO2_ALLOC_OPT_LOCK_MASK) {
 	case AO2_ALLOC_OPT_LOCK_MUTEX:
 		obj_mutex = INTERNAL_OBJ_MUTEX(user_data);
@ -322,6 +351,10 @@ int __ao2_trylock(void *user_data, enum ao2_lock_req lock_how, const char *file,
 		return -1;
 	}

+	if (ref_log) {
+		obj->priv_data.lockused  = 1;
+	}
+
 	switch (obj->priv_data.options & AO2_ALLOC_OPT_LOCK_MASK) {
 	case AO2_ALLOC_OPT_LOCK_MUTEX:
 		obj_mutex = INTERNAL_OBJ_MUTEX(user_data);
@ -369,7 +402,6 @@ int __ao2_trylock(void *user_data, enum ao2_lock_req lock_how, const char *file,
 		return -1;
 	}

-
 	return res;
 }

@ -473,9 +505,7 @@ 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) {
@ -595,33 +625,25 @@ 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
+		lock_state = obj->priv_data.lockused ? "used" : "unused";
 		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
+		lock_state = obj->priv_data.lockused ? "used" : "unused";
 		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
+		lock_state = obj->priv_data.lockused ? "used" : "unused";
 		ao2_t_ref(obj_lockobj->lockobj.lock, -1, "release lockobj");

 		ast_free(obj_lockobj);
@ -629,22 +651,13 @@ 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%s**,%s\n",
-			user_data, delta, ast_get_tid(), file, line, func,
-#ifdef DEBUG_THREADS
-			"**lock-state:",
-			lock_state,
-#else
-			"", "",
-#endif
-			tag);
+		fprintf(ref_log, "%p,%d,%d,%s,%d,%s,**destructor**lock-state:%s**,%s\n",
+			user_data, delta, ast_get_tid(), file, line, func, lock_state, tag);
 		fflush(ref_log);
 	}

@ -673,10 +686,12 @@ static void *internal_ao2_alloc(size_t data_size, ao2_destructor_fn destructor_f
 	struct astobj2_lock *obj_mutex;
 	struct astobj2_rwlock *obj_rwlock;
 	struct astobj2_lockobj *obj_lockobj;
+	size_t overhead;

 	switch (options & AO2_ALLOC_OPT_LOCK_MASK) {
 	case AO2_ALLOC_OPT_LOCK_MUTEX:
-		obj_mutex = __ast_calloc(1, sizeof(*obj_mutex) + data_size, file, line, func);
+		overhead = sizeof(*obj_mutex);
+		obj_mutex = __ast_calloc(1, overhead + data_size, file, line, func);
 		if (obj_mutex == NULL) {
 			return NULL;
 		}
@ -685,7 +700,8 @@ static void *internal_ao2_alloc(size_t data_size, ao2_destructor_fn destructor_f
 		obj = (struct astobj2 *) &obj_mutex->priv_data;
 		break;
 	case AO2_ALLOC_OPT_LOCK_RWLOCK:
-		obj_rwlock = __ast_calloc(1, sizeof(*obj_rwlock) + data_size, file, line, func);
+		overhead = sizeof(*obj_rwlock);
+		obj_rwlock = __ast_calloc(1, overhead + data_size, file, line, func);
 		if (obj_rwlock == NULL) {
 			return NULL;
 		}
@ -694,7 +710,8 @@ static void *internal_ao2_alloc(size_t data_size, ao2_destructor_fn destructor_f
 		obj = (struct astobj2 *) &obj_rwlock->priv_data;
 		break;
 	case AO2_ALLOC_OPT_LOCK_NOLOCK:
-		obj = __ast_calloc(1, sizeof(*obj) + data_size, file, line, func);
+		overhead = sizeof(*obj);
+		obj = __ast_calloc(1, overhead + data_size, file, line, func);
 		if (obj == NULL) {
 			return NULL;
 		}
@ -706,7 +723,8 @@ static void *internal_ao2_alloc(size_t data_size, ao2_destructor_fn destructor_f
 			return NULL;
 		}

-		obj_lockobj = __ast_calloc(1, sizeof(*obj_lockobj) + data_size, file, line, func);
+		overhead = sizeof(*obj_lockobj);
+		obj_lockobj = __ast_calloc(1, overhead + data_size, file, line, func);
 		if (obj_lockobj == NULL) {
 			ao2_t_ref(lockobj, -1, "release lockobj for failed alloc");
 			return NULL;
@ -735,8 +753,8 @@ static void *internal_ao2_alloc(size_t data_size, ao2_destructor_fn destructor_f
 #endif

 	if (ref_log && tag) {
-		fprintf(ref_log, "%p,+1,%d,%s,%d,%s,**constructor**,%s\n",
-			EXTERNAL_OBJ(obj), ast_get_tid(), file, line, func, tag);
+		fprintf(ref_log, "%p,+1,%d,%s,%d,%s,**constructor**%zu**%zu**,%s\n",
+			EXTERNAL_OBJ(obj), ast_get_tid(), file, line, func, overhead, data_size, tag);
 		fflush(ref_log);
 	}