[Asterisk-code-review] refdebug: Create refstats.py script. (asterisk[16])

Corey Farrell asteriskteam at digium.com
Wed Oct 10 06:11:14 CDT 2018


Corey Farrell has uploaded this change for review. ( https://gerrit.asterisk.org/10457


Change subject: refdebug: Create refstats.py script.
......................................................................

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.

Change-Id: I84e9d679cc86d772cc97c888d9d856a17e0d3a4a
---
M contrib/Makefile
M contrib/scripts/refcounter.py
M contrib/scripts/reflocks.py
A contrib/scripts/refstats.py
M main/astobj2.c
5 files changed, 217 insertions(+), 44 deletions(-)



  git pull ssh://gerrit.asterisk.org:29418/asterisk refs/changes/57/10457/1

diff --git a/contrib/Makefile b/contrib/Makefile
index 9512de5..074a12b 100644
--- a/contrib/Makefile
+++ b/contrib/Makefile
@@ -25,9 +25,13 @@
 	$(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"
diff --git a/contrib/scripts/refcounter.py b/contrib/scripts/refcounter.py
index 36fb341..146a024 100755
--- a/contrib/scripts/refcounter.py
+++ b/contrib/scripts/refcounter.py
@@ -108,8 +108,10 @@
             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(
diff --git a/contrib/scripts/reflocks.py b/contrib/scripts/reflocks.py
index 7d8edfc..db1985f 100755
--- a/contrib/scripts/reflocks.py
+++ b/contrib/scripts/reflocks.py
@@ -48,7 +48,6 @@
                     object_types[obj_type] = {
                         'used': 0,
                         'unused': 0,
-                        'lockobj': 0,
                         'none': 0
                     }
                 objects[addr] = obj_type
@@ -62,8 +61,6 @@
                     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 @@
             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 @@
     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)
 
diff --git a/contrib/scripts/refstats.py b/contrib/scripts/refstats.py
new file mode 100755
index 0000000..93df02f
--- /dev/null
+++ 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 at 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))
diff --git a/main/astobj2.c b/main/astobj2.c
index d6a8a4e..66b6495 100644
--- a/main/astobj2.c
+++ b/main/astobj2.c
@@ -63,13 +63,15 @@
 	int32_t ref_counter;
 	/*! The ao2 object option flags */
 	uint32_t options:2;
+	/*! Set to 1 when the lock is used if refdebug is enabled. */
+	uint32_t lockused:1;
 	/*! magic number.  This is used to verify that a pointer passed in is a
 	 *  valid astobj2 or ao2_weak reference */
-	uint32_t magic:30;
+	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 +208,10 @@
 		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 +328,10 @@
 		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 +379,6 @@
 		return -1;
 	}
 
-
 	return res;
 }
 
@@ -473,9 +482,7 @@
 	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 +602,25 @@
 	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 +628,13 @@
 	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 +663,12 @@
 	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 +677,8 @@
 		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 +687,8 @@
 		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 +700,8 @@
 			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 +730,8 @@
 #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);
 	}
 

-- 
To view, visit https://gerrit.asterisk.org/10457
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings

Gerrit-Project: asterisk
Gerrit-Branch: 16
Gerrit-MessageType: newchange
Gerrit-Change-Id: I84e9d679cc86d772cc97c888d9d856a17e0d3a4a
Gerrit-Change-Number: 10457
Gerrit-PatchSet: 1
Gerrit-Owner: Corey Farrell <git at cfware.com>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20181010/9699d40b/attachment-0001.html>


More information about the asterisk-code-review mailing list