refdebug: Create refstats.py script.
authorCorey Farrell <git@cfware.com>
Wed, 10 Oct 2018 09:37:23 +0000 (05:37 -0400)
committerCorey Farrell <git@cfware.com>
Mon, 15 Oct 2018 20:35:35 +0000 (15:35 -0500)
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
contrib/scripts/refcounter.py
contrib/scripts/reflocks.py
contrib/scripts/refstats.py [new file with mode: 0755]
main/astobj2.c

index 9512de5..074a12b 100644 (file)
@@ -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"
index 36fb341..146a024 100755 (executable)
@@ -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(
index 7d8edfc..db1985f 100755 (executable)
@@ -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 (executable)
index 0000000..93df02f
--- /dev/null
@@ -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))
index d6a8a4e..ebc0720 100644 (file)
@@ -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);
        }