Repository: scoutapp/scout_apm_python
Pull request #115 (2018-08-21 16:35:18)

v1.3.0. Object allocation tracing, Mem Delta for Tracked Requests
v1.3.0.
Implements object allocation tracing via extension module.
Reports the memory delta in MB for Tracked Requests.


Patch:
diff --git a/.travis.yml b/.travis.yml
index ae768f5..2f578c9 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -1,9 +1,17 @@
+env:
+  global:
+    - TWINE_USERNAME=scout
+    - secure: "ohvspT59/b71SdnIFf/HA5552tGaYWLYTUV2IQ/ZNxrTiJd/hcm5eBbfAkOUiC6l2cxdHt+cAyRh27us32z7F29qzlSzrWkTD18pvFKjSGtaa2X0aBTiollfiGgiXpdT5wiDoyjyGWti3q4CpwOZjrpB/rZx0DUxdRejf0cQfs/6W8xqei/PeSTAY+58eRxKUo9JOsEObDgpjJFSWTHVip6Rm0C8zG5fEal6OEMozP+LncSzxIPZiaA0x82nYSMSBQiJXqgX6x1iNDUVl9W1wwghPjCxhz1n6kUtoKOnLcz2VhtmzR+rFDXcdgIr3l9HsSaj8t/jRIPwyUuB1DDamKWuEC0dFrqeTraOKz/t7eZkSpKa+jRaNUC4RLPSSNJVC3hEH8WlNIAyCGyvYv0RAGEYzrWcl0QZQgn1s205uIVKF8v3bepAV4oPUOEjhAk3+kVhBDLrUHWnDtLzQxPJOcC/PpMIkXx5+ZCADJrkmppEAtv+gAbHIE5gcodvyGgUc1ynp/Ul2LQxUX7KUopZBkBtFomRJWOXli5rV9tc8It+m91Xua6+jRB8UePyHw2KLGoABulNNoGSvr+uRdH8Ph/4des33iikTEnEDBk740NAsMW1pExMMlXAdaYScpBjCu7z3MrSCs4oraCVJ1g9nqbc7ugxVqMPC97fu7XKpe8="
+
 language: python
 matrix:
   include:
     - python: 3.4
     - python: 3.5
     - python: 3.6
+    - python: 3.7
+      dist: xenial
+      sudo: true
     - python: "pypy3"
 
 cache: pip
@@ -25,7 +33,15 @@ install:
   - tox --version
 
 script:
-  - tox -v
+  - tox -v --workdir=/tmp/tox
+  - python setup.py bdist_wheel
+  - if [ "${TRAVIS_PYTHON_VERSION:-}" == "3.6" ]; then
+      python setup.py sdist;
+    fi
+  - if [ "${TRAVIS_TAG:-}" != "" ]; then
+      pip install twine;
+      python -m twine upload --skip-existing dist/*;
+    fi
 
 after_failure:
   - more .tox/log/* | cat
@@ -35,20 +51,3 @@ notifications:
   email:
     on_success: never
     on_failure: always
-
-# branches:
-#   only:
-#     # release tags
-#     - /^v\d+\.\d+\.\d+.*$/
-#     - master
-
-deploy:
-  provider: pypi
-  user: scout
-  distributions: sdist bdist_wheel
-  password:
-    secure: "MPs+ybUn50YCD+oSXdLnIyHiKf5ZU4JB6rzFkesWEf2fFglX3mMUoZ1xfHUTuNJLMf4Jp6+UNNMRGIAFkNLPrYaNmUYiVyZKIqwgNzB/+9lyTAj/gVOrO8zEZrEslaZYVWwv8NAyR3TjjoFwRN49F23aGT0zqKB9wdec2WRN0I7HqYDbOyEDgVJXnPSxvTJK6PCgLoRTN+pgATpGXLODQeem74T88ApgFixGwqXSTc8JqTp52JRYtxYYZGeFtlExiB42PoUkGMozP/LIpMPgVite7zEoIJNcGqA0Yr55xOBnsAJM34jJzVz/Kn1i8c0RyJXmTypLnjEAtmIAfuPSGja/3Tw8ARvvPWMLVrvBGqCLZPgn/nZDIr3XsTrmpzPnwHne2Q4juPwQzOZHYZ5U6DmQb/NoSzqCK2QGVEQNT8gEEyZVPeUiPeHmPeqHPk5IRBiT/YiL84kXA+r44EDcpfTYdrjBw4gHf1T+qru3BPgpk2QF3EJOtC3D1q0fBzmBhXFSU1W2BEFnw58l2wHMSLeKm0zN/gOZ0hnNgTw02sfb67RgWi7WY3Yj8BBNp6S98YB73lbkJ9Aw0wM53WA9kcEVaQ6DXHqI9WSSrqXhMFEFZPgSaP48e1f4g/VasncadrZ67voMwhhGnumyV6aV06QSscvLa1Y+QF/tYMSFcsI="
-  on:
-    tags: true
-    repo: scoutapp/scout_apm_python
-    condition: "$TRAVIS_PYTHON_VERSION = 3.6"
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 90b5ce2..e2b39cd 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,5 +1,16 @@
 # Changelog
 
+## [1.3.0] 2018-08-20
+
+### Added
+
+- Track object allocations for every span (Objtrace module)
+- Track RSS increase during a TrackedRequest.
+
+### Fixed
+
+- Compatibility with old style Django middleware/settings
+
 ## [1.2.3] 2018-08-15
 
 ### Added
diff --git a/setup.cfg b/setup.cfg
index 3480374..48ddb6f 100644
--- a/setup.cfg
+++ b/setup.cfg
@@ -1,2 +1,1 @@
-[bdist_wheel]
-universal=1
\ No newline at end of file
+# Intentionally empty
\ No newline at end of file
diff --git a/setup.py b/setup.py
index 2de8b8a..8f3f1f8 100644
--- a/setup.py
+++ b/setup.py
@@ -1,34 +1,41 @@
 from glob import glob
 import os
+import sys
 
-from setuptools import find_packages, setup
+from setuptools import find_packages, setup, Extension
 
 long_description = 'Scout Application Performance Monitoring Agent - https://scoutapp.com'
 if os.path.exists('README.md'):
     long_description = open('README.md').read()
 
-setup(name='scout_apm',
-      version='1.2.3',
-      description='Scout Application Performance Monitoring Agent',
-      long_description=long_description,
-      long_description_content_type='text/markdown',
-      url='https://github.com/scoutapp/scout_apm_python',
-      author='Scout',
-      author_email='support@scoutapp.com',
-      license='MIT',
-      zip_safe=False,
-      python_requires='>=3.4, <4',
-      packages=find_packages('src'),
-      package_dir={'': 'src'},
-      py_modules=[os.splitext(os.basename(path))[0] for path in glob('src/*.py')],
-      entry_points={
+# Try to compile the extensions, except for platforms or versions
+# where our extensions are not supported
+compile_extensions = True
+
+setup_args = {
+      'name': 'scout_apm',
+      'version': '1.3.0',
+      'description': 'Scout Application Performance Monitoring Agent',
+      'long_description': long_description,
+      'long_description_content_type': 'text/markdown',
+      'url': 'https://github.com/scoutapp/scout_apm_python',
+      'author': 'Scout',
+      'author_email': 'support@scoutapp.com',
+      'license': 'MIT',
+      'zip_safe': False,
+      'python_requires': '>=3.4, <4',
+      'packages': find_packages('src'),
+      'package_dir': {'': 'src'},
+      'py_modules': [os.splitext(os.basename(path))[0] for path in glob('src/*.py')],
+      'ext_modules': [Extension('scout_apm.core.objtrace', ['src/scout_apm/core/ext/objtrace.c'])],
+      'entry_points': {
           'console_scripts': [
               'core-agent-manager = scout_apm.core.cli.core_agent_manager:main'
           ]
       },
-      install_requires=['psutil', 'PyYAML', 'requests'],
-      keywords='apm performance monitoring development',
-      classifiers=[
+      'install_requires': ['psutil', 'PyYAML', 'requests'],
+      'keywords': 'apm performance monitoring development',
+      'classifiers': [
         'Development Status :: 5 - Production/Stable',
         'Intended Audience :: Developers',
         'Topic :: System :: Monitoring',
@@ -41,4 +48,18 @@ setup(name='scout_apm',
         'Programming Language :: Python :: 3.5',
         'Programming Language :: Python :: 3.6',
         'Programming Language :: Python :: 3.7',
-      ])
+      ]}
+
+if sys.version_info <= (3, 0):
+    compile_extensions = False
+
+if sys.platform.startswith('java'):
+    compile_extensions = False
+
+if '__pypy__' in sys.builtin_module_names:
+    compile_extensions = False
+
+if compile_extensions is not True:
+    del setup_args['ext_modules']
+
+setup(**setup_args)
diff --git a/src/scout_apm/core/__init__.py b/src/scout_apm/core/__init__.py
index 17adfaa..6e519c2 100644
--- a/src/scout_apm/core/__init__.py
+++ b/src/scout_apm/core/__init__.py
@@ -10,6 +10,12 @@ from scout_apm.core.core_agent_manager import CoreAgentManager
 from scout_apm.core.instrument_manager import InstrumentManager
 from scout_apm.core.metadata import AppMetadata
 
+try:
+    from scout_apm.core import objtrace
+    HAS_OBJTRACE = True
+except ImportError:
+    HAS_OBJTRACE = False
+
 logger = logging.getLogger(__name__)
 
 
@@ -24,6 +30,9 @@ def install(*args, **kwargs):
 
     InstrumentManager().install_all()
 
+    if HAS_OBJTRACE:
+        objtrace.enable()
+
     logger.debug('APM Launching on PID: %s', getpid())
     CoreAgentManager().launch()
 
diff --git a/src/scout_apm/core/ext/objtrace.c b/src/scout_apm/core/ext/objtrace.c
new file mode 100644
index 0000000..26a2d86
--- /dev/null
+++ b/src/scout_apm/core/ext/objtrace.c
@@ -0,0 +1,177 @@
+#include "Python.h"
+#include <stdlib.h>
+#include <limits.h>
+
+#define VERSION "1.0.0"
+
+static int enabled = 0;
+static int installed = 0;
+
+#if PY_VERSION_HEX >= 0x03050000
+#  define FAIL_CALLOC
+#  define PyMemAllocator PyMemAllocatorEx
+#endif
+
+struct {
+    PyMemAllocator obj;
+} hook;
+
+static __thread unsigned long long allocs = 0;
+static __thread unsigned long long callocs = 0;
+static __thread unsigned long long reallocs = 0;
+static __thread unsigned long long frees = 0;
+
+static void* hook_malloc(void *ctx, size_t size)
+{
+    if (allocs == ULLONG_MAX) {
+        allocs = 0;
+    }
+
+    allocs++;
+    PyMemAllocator *alloc = (PyMemAllocator *)ctx;
+    return alloc->malloc(alloc->ctx, size);
+}
+
+#ifdef FAIL_CALLOC
+static void* hook_calloc(void *ctx, size_t nelem, size_t elsize)
+{
+    if (callocs == ULLONG_MAX) {
+        callocs = 0;
+    }
+
+    callocs++;
+    PyMemAllocator *alloc = (PyMemAllocator *)ctx;
+    return alloc->calloc(alloc->ctx, nelem, elsize);
+}
+#endif
+
+static void* hook_realloc(void *ctx, void *ptr, size_t new_size)
+{
+    if (reallocs == ULLONG_MAX) {
+        reallocs = 0;
+    }
+
+    reallocs++;
+    PyMemAllocator *alloc = (PyMemAllocator *)ctx;
+    return alloc->realloc(alloc->ctx, ptr, new_size);
+}
+
+static void hook_free(void *ctx, void *ptr)
+{
+    if (frees == ULLONG_MAX) {
+        frees = 0;
+    }
+
+    frees++;
+    PyMemAllocator *alloc = (PyMemAllocator *)ctx;
+    alloc->free(alloc->ctx, ptr);
+}
+
+static void setup_hooks(void)
+{
+    PyMemAllocator alloc;
+
+    alloc.malloc = hook_malloc;
+#ifdef FAIL_CALLOC
+    alloc.calloc = hook_calloc;
+#endif
+    alloc.realloc = hook_realloc;
+    alloc.free = hook_free;
+    PyMem_GetAllocator(PYMEM_DOMAIN_OBJ, &hook.obj);
+
+    alloc.ctx = &hook.obj;
+    PyMem_SetAllocator(PYMEM_DOMAIN_OBJ, &alloc);
+}
+
+static void remove_hooks(void)
+{
+    PyMem_SetAllocator(PYMEM_DOMAIN_OBJ, &hook.obj);
+}
+
+static PyObject*
+objtrace_enable(PyObject *module)
+{
+    enabled = 1;
+    if (!installed) {
+        installed = 1;
+        setup_hooks();
+    }
+    Py_RETURN_NONE;
+}
+
+static PyObject*
+objtrace_disable(PyObject *module)
+{
+    if (installed) {
+        installed = 0;
+        remove_hooks();
+    }
+    enabled = 0;
+    Py_RETURN_NONE;
+}
+
+static PyObject*
+objtrace_get_counts(PyObject *module)
+{
+    return Py_BuildValue("KKKK", allocs, callocs, reallocs, frees);
+}
+
+static PyObject*
+objtrace_reset_counts(PyObject *module)
+{
+    allocs = 0;
+    callocs = 0;
+    reallocs = 0;
+    frees = 0;
+
+    Py_RETURN_NONE;
+}
+
+PyDoc_STRVAR(module_doc,
+"scout_apm.core.objtrace module.");
+
+static PyMethodDef module_methods[] = {
+    {"enable",
+     (PyCFunction)objtrace_enable, METH_NOARGS,
+     PyDoc_STR("enable()")},
+    {"disable",
+     (PyCFunction)objtrace_disable, METH_NOARGS,
+     PyDoc_STR("disable()")},
+    {"get_counts",
+     (PyCFunction)objtrace_get_counts, METH_NOARGS,
+     PyDoc_STR("get_counts()")},
+    {"reset_counts",
+     (PyCFunction)objtrace_reset_counts, METH_NOARGS,
+     PyDoc_STR("reset_counts()")},
+    {NULL, NULL}  /* sentinel */
+};
+
+static struct PyModuleDef module_def = {
+    PyModuleDef_HEAD_INIT,
+    "scout_apm.core.objtrace",
+    module_doc,
+    0, /* non-negative size to be able to unload the module */
+    module_methods,
+    NULL,
+    NULL,
+    NULL,
+    NULL
+};
+
+PyMODINIT_FUNC
+PyInit_objtrace(void)
+{
+    PyObject *m, *version;
+
+    m = PyModule_Create(&module_def);
+    if (m == NULL)
+        return NULL;
+
+    version = PyUnicode_FromString(VERSION);
+    if (version == NULL)
+        return NULL;
+
+    PyModule_AddObject(m, "__version__", version);
+    return m;
+}
+
diff --git a/src/scout_apm/core/samplers/memory.py b/src/scout_apm/core/samplers/memory.py
index 5127ba6..9aba33a 100644
--- a/src/scout_apm/core/samplers/memory.py
+++ b/src/scout_apm/core/samplers/memory.py
@@ -26,6 +26,13 @@ class Memory(object):
     def rss_in_mb():
         return Memory.rss_to_mb(Memory.rss())
 
+    @staticmethod
+    def get_delta(prior_rss_in_mb):
+        mem = Memory.rss_in_mb()
+        if mem > prior_rss_in_mb:
+            return mem - prior_rss_in_mb
+        return 0.0
+
     def metric_type(self):
         return 'Memory'
 
diff --git a/src/scout_apm/core/tracked_request.py b/src/scout_apm/core/tracked_request.py
index 4e25d09..0dab5c8 100644
--- a/src/scout_apm/core/tracked_request.py
+++ b/src/scout_apm/core/tracked_request.py
@@ -8,8 +8,15 @@ from scout_apm.core.samplers import Samplers
 from scout_apm.core.request_manager import RequestManager
 from scout_apm.core.thread_local import ThreadLocalSingleton
 from scout_apm.core.n_plus_one_call_set import NPlusOneCallSet
+from scout_apm.core.samplers import Memory
 import scout_apm.core.backtrace
 
+try:
+    from scout_apm.core import objtrace
+    HAS_OBJTRACE = True
+except ImportError:
+    HAS_OBJTRACE = False
+
 # Logging
 logger = logging.getLogger(__name__)
 
@@ -28,6 +35,7 @@ class TrackedRequest(ThreadLocalSingleton):
         self.complete_spans = kwargs.get('complete_spans', [])
         self.tags = kwargs.get('tags', {})
         self.real_request = kwargs.get('real_request', False)
+        self.memory_start = kwargs.get('memory_start', Memory.rss_in_mb())
         self.callset = NPlusOneCallSet()
         logger.debug('Starting request: %s', self.req_id)
 
@@ -87,8 +95,9 @@ class TrackedRequest(ThreadLocalSingleton):
         logger.debug('Stopping request: %s', self.req_id)
         if self.end_time is None:
             self.end_time = datetime.utcnow()
-        RequestManager.instance().add_request(self)
         if self.is_real_request():
+            self.tag('mem_delta', Memory.get_delta(self.memory_start))
+            RequestManager.instance().add_request(self)
             Samplers.ensure_running()
 
         # This can fail if the Tracked Request was created directly, not through instance()
@@ -109,9 +118,18 @@ class Span:
         self.ignore_children = kwargs.get('ignore_children', False)
         self.parent = kwargs.get('parent', None)
         self.tags = kwargs.get('tags', {})
+        if HAS_OBJTRACE:
+            self.start_objtrace_counts = kwargs.get('start_objtrace_counts', objtrace.get_counts())
+        else:
+            self.start_objtrace_counts = kwargs.get('start_objtrace_counts', (0, 0, 0, 0))
+        self.end_objtrace_counts = kwargs.get('end_objtrace_counts', (0, 0, 0, 0))
 
     def stop(self):
         self.end_time = datetime.utcnow()
+        if HAS_OBJTRACE:
+            self.end_objtrace_counts = objtrace.get_counts()
+        else:
+            self.end_objtrace_counts = (0, 0, 0, 0)
 
     def tag(self, key, value):
         if key in self.tags:
@@ -132,6 +150,8 @@ class Span:
     # Add any interesting annotations to the span. Assumes that we are in the
     # process of stopping this span.
     def annotate(self):
+        self.tag('allocations', self.calculate_allocations())
+        # Don't capture backtraces for Controller or Middleware
         if self.operation is not None:
             if self.operation.startswith('Controller') or self.operation.startswith('Middleware'):
                 return
@@ -139,6 +159,28 @@ class Span:
         if self.duration() > slow_threshold:
             self.capture_backtrace()
 
+    def calculate_allocations(self):
+        if HAS_OBJTRACE is False:
+            return 0
+
+        start_allocs = self.start_objtrace_counts[0] + self.start_objtrace_counts[1] + self.start_objtrace_counts[2]
+        end_allocs = self.end_objtrace_counts[0] + self.end_objtrace_counts[1] + self.end_objtrace_counts[2]
+        try:
+            # If even one of the counters rolled over, we're pretty much
+            # guaranteed to have end_allocs be less than start_allocs.
+            # This should rarely happen. Max Unsigned Long Long is a big number
+            if end_allocs - start_allocs < 0:
+                logger.debug('End allocation count smaller than start '
+                             'allocation count for span {}: start = {}, '
+                             'end = {}'.format(self.span_id,
+                                               start_allocs,
+                                               end_allocs))
+                return 0
+            return end_allocs - start_allocs
+        except TypeError as e:
+            logger.debug('Exception in calculate_allocations: {}'.format(repr(e)))
+            return 0
+
     def capture_backtrace(self):
         stack = scout_apm.core.backtrace.capture()
         self.tag('stack', stack)


Test patch:
diff --git a/tests/scout_apm_tests/api/instrument_test.py b/tests/scout_apm_tests/api/instrument_test.py
index 20b4502..59f3f3e 100644
--- a/tests/scout_apm_tests/api/instrument_test.py
+++ b/tests/scout_apm_tests/api/instrument_test.py
@@ -58,7 +58,6 @@ def test_context_manager_default_tags():
         a = 1
 
     span = tr.complete_spans[-1]
-    assert(len(span.tags) == 1)
     assert(span.tags['x'] == 99)
 
 
@@ -72,7 +71,6 @@ def test_decoration_default_tags():
     test()
 
     span = tr.complete_spans[-1]
-    assert(len(span.tags) == 1)
     assert(span.tags['x'] == 99)
 
 
diff --git a/tests/scout_apm_tests/commands_test.py b/tests/scout_apm_tests/commands_test.py
index 5794fd3..4bb96ed 100644
--- a/tests/scout_apm_tests/commands_test.py
+++ b/tests/scout_apm_tests/commands_test.py
@@ -30,4 +30,4 @@ def test_from_tracked_request_creates_batch_command():
     tr.stop_span()
 
     batch = scout_apm.core.commands.BatchCommand.from_tracked_request(tr)
-    assert(len(batch.commands) == 4)
+    assert(len(batch.commands) == 5)
diff --git a/tests/scout_apm_tests/objtrace_test.py b/tests/scout_apm_tests/objtrace_test.py
new file mode 100644
index 0000000..1b04353
--- /dev/null
+++ b/tests/scout_apm_tests/objtrace_test.py
@@ -0,0 +1,40 @@
+import unittest
+
+try:
+    from scout_apm.core import objtrace
+    HAS_OBJTRACE = True
+except ImportError:
+    HAS_OBJTRACE = False
+
+
+if HAS_OBJTRACE:
+    class TestObjtrace(unittest.TestCase):
+        def setUp(self):
+            objtrace.reset_counts()
+
+        def tearDown(self):
+            objtrace.reset_counts()
+
+        def test_enables_and_disabled(self):
+            objtrace.enable()
+            objtrace.get_counts()
+            objtrace.disable()
+
+        def test_allocation_counts(self):
+            l = []
+            objtrace.enable()
+            for _ in range(100):
+                l.append([1])
+            objtrace.disable()
+            c = objtrace.get_counts()
+            assert(c[0] > 0)
+
+        def test_frees_counts(self):
+            objtrace.enable()
+            for x in (1, 2, 3):
+                y = x
+            c = objtrace.get_counts()
+            assert(c[3] > 0)
+
+    if __name__ == '__main__':
+        unittest.main()
diff --git a/tests/scout_apm_tests/tracked_request_test.py b/tests/scout_apm_tests/tracked_request_test.py
index 6d74102..83ea2a1 100644
--- a/tests/scout_apm_tests/tracked_request_test.py
+++ b/tests/scout_apm_tests/tracked_request_test.py
@@ -2,6 +2,12 @@ from datetime import datetime, timedelta
 
 from scout_apm.core.tracked_request import TrackedRequest
 
+try:
+    from scout_apm.core import objtrace
+    HAS_OBJTRACE = True
+except ImportError:
+    HAS_OBJTRACE = False
+
 
 def test_instance():
     tr1 = TrackedRequest.instance()
@@ -25,7 +31,6 @@ def test_tag_span():
     span.tag("a", "b")
     tr.stop_span()
 
-    assert(len(tr.complete_spans[0].tags) == 1)
     assert(tr.complete_spans[0].tags['a'] == 'b')
 
 
@@ -37,6 +42,14 @@ def test_start_span_wires_parents():
     assert(span2.parent == span1.span_id)
 
 
+def test_tags_allocations_for_spans():
+    if HAS_OBJTRACE:
+        tr = TrackedRequest()
+        span = tr.start_span()
+        tr.stop_span()
+        assert(span.tags['allocations'] > 0)
+
+
 def test_start_span_does_not_ignore_children():
     tr = TrackedRequest()
     tr.start_span(operation='parent')