feat(profiling): extract class name from stack traces (#4012)

This adds an heuristic for extracting class names from stack traces. This is
far from being perfect, as it relies on the convention of using `self` and
`cls` as name for the local variable in a function call to designate instances
or classes.

However, that ought to be enough for the vast majority of the Python program
seen in the wild.

Author: jd

.github/workflows/test_frameworks.yml

@@ -366,10 +366,11 @@ jobs:
         run: pip install ../ddtrace
       - name: Install dependencies
         run: |
-          python -m pip install -U pip setuptools wheel
+          python -m pip install -U pip setuptools wheel pytest
           python -m pip install -e .[test]
       - name: Run tests
-        run: ddtrace-run python setup.py test
+        # Disable tests checking GC references since profiling can interfere
+        run: ddtrace-run python -m pytest -k 'not test_record_gc and not test_record_get and not test_record_items and not test_record_iter' tests
 
   pylons-testsuite-1_0_3:
     name: Pylons 1.0.3

ddtrace/profiling/collector/_memalloc_tb.c

@@ -13,6 +13,8 @@ static traceback_t* traceback_buffer = NULL;
 /* A string containing "<unknown>" just in case we can't store the real function
  * or file name. */
 static PyObject* unknown_name = NULL;
+/* A string containing "" */
+static PyObject* empty_string = NULL;
 
 #define TRACEBACK_SIZE(NFRAME) (sizeof(traceback_t) + sizeof(frame_t) * (NFRAME - 1))
 
@@ -26,6 +28,13 @@ memalloc_tb_init(uint16_t max_nframe)
         PyUnicode_InternInPlace(&unknown_name);
     }
 
+    if (empty_string == NULL) {
+        empty_string = PyUnicode_FromString("");
+        if (empty_string == NULL)
+            return -1;
+        PyUnicode_InternInPlace(&empty_string);
+    }
+
     /* Allocate a buffer that can handle the largest traceback possible.
        This will be used a temporary buffer when converting stack traces. */
     traceback_buffer = PyMem_RawMalloc(TRACEBACK_SIZE(max_nframe));
@@ -171,7 +180,7 @@ traceback_to_tuple(traceback_t* tb)
     PyObject* stack = PyTuple_New(tb->nframe);
 
     for (uint16_t nframe = 0; nframe < tb->nframe; nframe++) {
-        PyObject* frame_tuple = PyTuple_New(3);
+        PyObject* frame_tuple = PyTuple_New(4);
 
         frame_t* frame = &tb->frames[nframe];
 
@@ -180,6 +189,9 @@ traceback_to_tuple(traceback_t* tb)
         PyTuple_SET_ITEM(frame_tuple, 1, PyLong_FromUnsignedLong(frame->lineno));
         PyTuple_SET_ITEM(frame_tuple, 2, frame->name);
         Py_INCREF(frame->name);
+        /* Class name */
+        PyTuple_SET_ITEM(frame_tuple, 3, empty_string);
+        Py_INCREF(empty_string);
 
         PyTuple_SET_ITEM(stack, nframe, frame_tuple);
     }

ddtrace/profiling/collector/_traceback.pyx

@@ -1,3 +1,25 @@
+cpdef _extract_class_name(frame):
+    # type: (...) -> str
+    """Extract class name from a frame, if possible.
+
+    :param frame: The frame object.
+    """
+    if frame.f_code.co_varnames:
+        argname = frame.f_code.co_varnames[0]
+        try:
+            value = frame.f_locals[argname]
+        except KeyError:
+            return ""
+        try:
+            if argname == "self":
+                return object.__getattribute__(type(value), "__name__")  # use type() and object.__getattribute__ to avoid side-effects
+            if argname == "cls":
+                return object.__getattribute__(value, "__name__")
+        except AttributeError:
+            return ""
+    return ""
+
+
 cpdef traceback_to_frames(traceback, max_nframes):
     """Serialize a Python traceback object into a list of tuple of (filename, lineno, function_name).
 
@@ -13,7 +35,7 @@ cpdef traceback_to_frames(traceback, max_nframes):
             frame = tb.tb_frame
             code = frame.f_code
             lineno = 0 if frame.f_lineno is None else frame.f_lineno
-            frames.insert(0, (code.co_filename, lineno, code.co_name))
+            frames.insert(0, (code.co_filename, lineno, code.co_name, _extract_class_name(frame)))
         nframes += 1
         tb = tb.tb_next
     return frames, nframes
@@ -32,6 +54,6 @@ cpdef pyframe_to_frames(frame, max_nframes):
         if len(frames) < max_nframes:
             code = frame.f_code
             lineno = 0 if frame.f_lineno is None else frame.f_lineno
-            frames.append((code.co_filename, lineno, code.co_name))
+            frames.append((code.co_filename, lineno, code.co_name, _extract_class_name(frame)))
         frame = frame.f_back
     return frames, nframes

ddtrace/profiling/event.py

@@ -8,8 +8,8 @@
 
 _T = typing.TypeVar("_T")
 
-# (filename, line number, function name)
-FrameType = typing.Tuple[str, int, str]
+# (filename, line number, function name, class name)
+FrameType = typing.Tuple[str, int, str, str]
 StackTraceType = typing.List[FrameType]
 
 

ddtrace/profiling/exporter/pprof.pyx

@@ -195,7 +195,7 @@ class _PprofConverter(object):
     _functions = attr.ib(
         init=False, factory=dict, type=typing.Dict[typing.Tuple[str, typing.Optional[str]], pprof_FunctionType]
     )
-    _locations = attr.ib(init=False, factory=dict, type=typing.Dict[event.FrameType, pprof_LocationType])
+    _locations = attr.ib(init=False, factory=dict, type=typing.Dict[typing.Tuple[str, int, str], pprof_LocationType])
     _string_table = attr.ib(init=False, factory=_StringTable)
 
     _last_location_id = attr.ib(init=False, factory=_Sequence)
@@ -257,7 +257,9 @@ class _PprofConverter(object):
         nframes,  # type: int
     ):
         # type: (...) -> typing.Tuple[int, ...]
-        locations = [self._to_Location(filename, lineno, funcname).id for filename, lineno, funcname in frames]
+        locations = [
+            self._to_Location(filename, lineno, funcname).id for filename, lineno, funcname, class_name in frames
+        ]
 
         omitted = nframes - len(frames)
         if omitted:
@@ -295,6 +297,7 @@ class _PprofConverter(object):
                 ("span id", span_id),
                 ("trace endpoint", trace_resource),
                 ("trace type", trace_type),
+                ("class name", frames[0][3]),
             ),
         )
 
@@ -369,6 +372,7 @@ class _PprofConverter(object):
                 ("trace endpoint", trace_resource),
                 ("trace type", trace_type),
                 ("lock name", lock_name),
+                ("class name", frames[0][3]),
             ),
         )
 
@@ -406,6 +410,7 @@ class _PprofConverter(object):
                 ("trace endpoint", trace_resource),
                 ("trace type", trace_type),
                 ("lock name", lock_name),
+                ("class name", frames[0][3]),
             ),
         )
 
@@ -439,6 +444,7 @@ class _PprofConverter(object):
                 ("trace endpoint", trace_resource),
                 ("trace type", trace_type),
                 ("exception type", exc_type_name),
+                ("class name", frames[0][3]),
             ),
         )
 

releasenotes/notes/profiling-export-stack-class-7e81bd42180b7220.yaml

@@ -0,0 +1,5 @@
+---
+features:
+  - |
+    profiler: collect and export the class name for the wall time, CPU
+    time and lock profiles, when available.

tests/profiling/collector/test_asyncio.py

@@ -24,7 +24,7 @@ async def test_lock_acquire_events():
     # It's called through pytest so I'm sure it's gonna be that long, right?
     assert len(event.frames) > 3
     assert event.nframes > 3
-    assert event.frames[0] == (__file__, 16, "test_lock_acquire_events")
+    assert event.frames[0] == (__file__, 16, "test_lock_acquire_events", "")
     assert event.sampling_pct == 100
 
 
@@ -45,7 +45,7 @@ async def test_asyncio_lock_release_events():
     # It's called through pytest so I'm sure it's gonna be that long, right?
     assert len(event.frames) > 3
     assert event.nframes > 3
-    assert event.frames[0] == (__file__, 38, "test_asyncio_lock_release_events")
+    assert event.frames[0] == (__file__, 38, "test_asyncio_lock_release_events", "")
     assert event.sampling_pct == 100
 
 

tests/profiling/collector/test_stack.py

@@ -88,6 +88,71 @@ def test_collect_once():
         pytest.fail("Unable to find MainThread")
 
 
+def _find_sleep_event(events, class_name):
+    class_method_found = False
+    class_classmethod_found = False
+
+    for e in events:
+        for frame in e.frames:
+            if frame[0] == __file__.replace(".pyc", ".py") and frame[2] == "sleep_class" and frame[3] == class_name:
+                class_method_found = True
+            elif (
+                frame[0] == __file__.replace(".pyc", ".py") and frame[2] == "sleep_instance" and frame[3] == class_name
+            ):
+                class_classmethod_found = True
+
+        if class_method_found and class_classmethod_found:
+            return True
+
+    return False
+
+
+def test_collect_once_with_class():
+    class SomeClass(object):
+        @classmethod
+        def sleep_class(cls):
+            # type: (...) -> bool
+            return cls().sleep_instance()
+
+        def sleep_instance(self):
+            # type: (...) -> bool
+            for _ in range(5):
+                if _find_sleep_event(r.events[stack_event.StackSampleEvent], "SomeClass"):
+                    return True
+                nogevent.sleep(1)
+            return False
+
+    r = recorder.Recorder()
+    s = stack.StackCollector(r)
+
+    with s:
+        assert SomeClass.sleep_class()
+
+
+def test_collect_once_with_class_not_right_type():
+    # type: (...) -> None
+    r = recorder.Recorder()
+
+    class SomeClass(object):
+        @classmethod
+        def sleep_class(foobar, cls):
+            # type: (...) -> bool
+            return foobar().sleep_instance(cls)
+
+        def sleep_instance(foobar, self):
+            # type: (...) -> bool
+            for _ in range(5):
+                if _find_sleep_event(r.events[stack_event.StackSampleEvent], ""):
+                    return True
+                nogevent.sleep(1)
+            return False
+
+    s = stack.StackCollector(r)
+
+    with s:
+        assert SomeClass.sleep_class(123)
+
+
 def _fib(n):
     if n == 1:
         return 1
@@ -309,7 +374,7 @@ def test_exception_collection_threads():
     assert e.sampling_period > 0
     assert e.thread_id in {t.ident for t in threads}
     assert isinstance(e.thread_name, str)
-    assert e.frames == [("<string>", 5, "_f30")]
+    assert e.frames == [("<string>", 5, "_f30", "")]
     assert e.nframes == 1
     assert e.exc_type == ValueError
     for t in threads:
@@ -333,7 +398,7 @@ def test_exception_collection():
     assert e.sampling_period > 0
     assert e.thread_id == nogevent.thread_get_ident()
     assert e.thread_name == "MainThread"
-    assert e.frames == [(__file__, 327, "test_exception_collection")]
+    assert e.frames == [(__file__, 392, "test_exception_collection", "")]
     assert e.nframes == 1
     assert e.exc_type == ValueError
 
@@ -365,7 +430,7 @@ def test_exception_collection_trace(
     assert e.sampling_period > 0
     assert e.thread_id == nogevent.thread_get_ident()
     assert e.thread_name == "MainThread"
-    assert e.frames == [(__file__, 354, "test_exception_collection_trace")]
+    assert e.frames == [(__file__, 419, "test_exception_collection_trace", "")]
     assert e.nframes == 1
     assert e.exc_type == ValueError
     assert e.span_id == span.span_id
@@ -647,7 +712,7 @@ def _nothing():
             else:
                 main_thread_found = True
         elif event.task_id in {t.ident for t in threads}:
-            for filename, lineno, funcname in event.frames:
+            for filename, lineno, funcname, classname in event.frames:
                 if funcname in (
                     "_nothing",
                     "sleep",

tests/profiling/collector/test_stack_asyncio.py

@@ -60,15 +60,15 @@ async def hello() -> None:
         if _asyncio_compat.PY37_AND_LATER:
             if event.task_name == "main":
                 assert event.thread_name == "MainThread"
-                assert event.frames == [(__file__, 30, "hello")]
+                assert event.frames == [(__file__, 30, "hello", "")]
                 assert event.nframes == 1
             elif event.task_name == t1_name:
                 assert event.thread_name == "MainThread"
-                assert event.frames == [(__file__, 24, "stuff")]
+                assert event.frames == [(__file__, 24, "stuff", "")]
                 assert event.nframes == 1
             elif event.task_name == t2_name:
                 assert event.thread_name == "MainThread"
-                assert event.frames == [(__file__, 24, "stuff")]
+                assert event.frames == [(__file__, 24, "stuff", "")]
                 assert event.nframes == 1
 
         if event.thread_name == "MainThread" and (