From 79677ead28f35a423318dac06d9346e647e6580d Mon Sep 17 00:00:00 2001
From: Corey Farrell <git@cfware.com>
Date: Wed, 10 Oct 2018 05:37:23 -0400
Subject: [PATCH] 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
---
contrib/Makefile | 4 +
contrib/scripts/refcounter.py | 6 +-
contrib/scripts/reflocks.py | 8 --
contrib/scripts/refstats.py | 180 ++++++++++++++++++++++++++++++++++
main/astobj2.c | 92 ++++++++++-------
5 files changed, 243 insertions(+), 47 deletions(-)
create mode 100755 contrib/scripts/refstats.py
diff --git a/contrib/Makefile b/contrib/Makefile
index 9512de540c..074a12b774 100644
--- 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"
diff --git a/contrib/scripts/refcounter.py b/contrib/scripts/refcounter.py
index 36fb34126a..146a024c90 100755
--- 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(
diff --git a/contrib/scripts/reflocks.py b/contrib/scripts/reflocks.py
index 7d8edfcd05..db1985f8a5 100755
--- 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)
diff --git a/contrib/scripts/refstats.py b/contrib/scripts/refstats.py
new file mode 100755
index 0000000000..93df02f64a
--- /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@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 d6a8a4eb45..ebc07200dd 100644
--- 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);
}
--
GitLab