fix(profiling): export lock acquire/release call location and variable name [backport 2.10]

ddtrace/profiling/collector/_lock.py

@@ -4,6 +4,7 @@
 import abc
 import os.path
 import sys
+import types
 import typing
 
 import attr
@@ -90,7 +91,8 @@ def __init__(
         self._self_export_libdd_enabled = export_libdd_enabled
         frame = sys._getframe(2 if WRAPT_C_EXT else 3)
         code = frame.f_code
-        self._self_name = "%s:%d" % (os.path.basename(code.co_filename), frame.f_lineno)
+        self._self_init_loc = "%s:%d" % (os.path.basename(code.co_filename), frame.f_lineno)
+        self._self_name: typing.Optional[str] = None
 
     def __aenter__(self):
         return self.__wrapped__.__aenter__()
@@ -110,6 +112,7 @@ def _acquire(self, inner_func, *args, **kwargs):
                 end = self._self_acquired_at = compat.monotonic_ns()
                 thread_id, thread_name = _current_thread()
                 task_id, task_name, task_frame = _task.get_task(thread_id)
+                lock_name = self._get_lock_call_loc_with_name() or self._self_init_loc
 
                 if task_frame is None:
                     frame = sys._getframe(1)
@@ -123,7 +126,7 @@ def _acquire(self, inner_func, *args, **kwargs):
 
                     handle = ddup.SampleHandle()
                     handle.push_monotonic_ns(end)
-                    handle.push_lock_name(self._self_name)
+                    handle.push_lock_name(lock_name)
                     handle.push_acquire(end - start, 1)  # AFAICT, capture_pct does not adjust anything here
                     handle.push_threadinfo(thread_id, thread_native_id, thread_name)
                     handle.push_task_id(task_id)
@@ -136,7 +139,7 @@ def _acquire(self, inner_func, *args, **kwargs):
                     handle.flush_sample()
                 else:
                     event = self.ACQUIRE_EVENT_CLASS(
-                        lock_name=self._self_name,
+                        lock_name=lock_name,
                         frames=frames,
                         nframes=nframes,
                         thread_id=thread_id,
@@ -169,6 +172,7 @@ def _release(self, inner_func, *args, **kwargs):
                         end = compat.monotonic_ns()
                         thread_id, thread_name = _current_thread()
                         task_id, task_name, task_frame = _task.get_task(thread_id)
+                        lock_name = self._get_lock_call_loc_with_name() or self._self_init_loc
 
                         if task_frame is None:
                             frame = sys._getframe(1)
@@ -182,7 +186,7 @@ def _release(self, inner_func, *args, **kwargs):
 
                             handle = ddup.SampleHandle()
                             handle.push_monotonic_ns(end)
-                            handle.push_lock_name(self._self_name)
+                            handle.push_lock_name(lock_name)
                             handle.push_release(
                                 end - self._self_acquired_at, 1
                             )  # AFAICT, capture_pct does not adjust anything here
@@ -199,7 +203,7 @@ def _release(self, inner_func, *args, **kwargs):
                             handle.flush_sample()
                         else:
                             event = self.RELEASE_EVENT_CLASS(
-                                lock_name=self._self_name,
+                                lock_name=lock_name,
                                 frames=frames,
                                 nframes=nframes,
                                 thread_id=thread_id,
@@ -233,6 +237,50 @@ def __enter__(self, *args, **kwargs):
     def __exit__(self, *args, **kwargs):
         self._release(self.__wrapped__.__exit__, *args, **kwargs)
 
+    def _maybe_update_lock_name(self, var_dict: typing.Dict):
+        if self._self_name:
+            return
+        for name, value in var_dict.items():
+            if name.startswith("__") or isinstance(value, types.ModuleType):
+                continue
+            if value is self:
+                self._self_name = name
+                break
+            if config.lock.name_inspect_dir:
+                for attribute in dir(value):
+                    if not attribute.startswith("__") and getattr(value, attribute) is self:
+                        self._self_name = attribute
+                        break
+
+    # Get lock acquire/release call location and variable name the lock is assigned to
+    def _get_lock_call_loc_with_name(self) -> typing.Optional[str]:
+        try:
+            # We expect the call stack to be like this:
+            # 0: this
+            # 1: _acquire/_release
+            # 2: acquire/release (or __enter__/__exit__)
+            # 3: caller frame
+            # And we expect additional frame if WRAPT_C_EXT is False
+            frame = sys._getframe(3 if WRAPT_C_EXT else 4)
+            code = frame.f_code
+            call_loc = "%s:%d" % (os.path.basename(code.co_filename), frame.f_lineno)
+
+            # First, look at the local variables of the caller frame, and then the global variables
+            self._maybe_update_lock_name(frame.f_locals)
+            self._maybe_update_lock_name(frame.f_globals)
+
+            if self._self_name:
+                return "%s:%s" % (call_loc, self._self_name)
+            else:
+                LOG.warning(
+                    "Failed to get lock variable name, we only support local/global variables and their attributes."
+                )
+                return call_loc
+
+        except Exception as e:
+            LOG.warning("Error getting lock acquire/release call location and variable name: %s", e)
+            return None
+
 
 class FunctionWrapper(wrapt.FunctionWrapper):
     # Override the __get__ method: whatever happens, _allocate_lock is always considered by Python like a "static"

ddtrace/settings/profiling.py

@@ -223,6 +223,15 @@ class Lock(En):
             help="Whether to enable the lock profiler",
         )
 
+        name_inspect_dir = En.v(
+            bool,
+            "name_inspect_dir",
+            default=True,
+            help_type="Boolean",
+            help="Whether to inspect the ``dir()`` of local and global variables to find the name of the lock. "
+            "With this enabled, the profiler finds the name of locks that are attributes of an object.",
+        )
+
     class Memory(En):
         __item__ = __prefix__ = "memory"
 

tests/profiling/collector/global_locks.py

@@ -0,0 +1,22 @@
+import threading
+
+
+global_lock = threading.Lock()
+
+
+def foo():
+    global global_lock
+    with global_lock:
+        pass
+
+
+class Bar:
+    def __init__(self):
+        self.bar_lock = threading.Lock()
+
+    def bar(self):
+        with self.bar_lock:
+            pass
+
+
+bar_instance = Bar()

tests/profiling/collector/test_asyncio.py

@@ -18,7 +18,7 @@ async def test_lock_acquire_events():
     assert len(r.events[collector_asyncio.AsyncioLockAcquireEvent]) == 1
     assert len(r.events[collector_asyncio.AsyncioLockReleaseEvent]) == 0
     event = r.events[collector_asyncio.AsyncioLockAcquireEvent][0]
-    assert event.lock_name == "test_asyncio.py:15"
+    assert event.lock_name == "test_asyncio.py:16:lock"
     assert event.thread_id == _thread.get_ident()
     assert event.wait_time_ns >= 0
     # It's called through pytest so I'm sure it's gonna be that long, right?
@@ -39,7 +39,7 @@ async def test_asyncio_lock_release_events():
     assert len(r.events[collector_asyncio.AsyncioLockAcquireEvent]) == 1
     assert len(r.events[collector_asyncio.AsyncioLockReleaseEvent]) == 1
     event = r.events[collector_asyncio.AsyncioLockReleaseEvent][0]
-    assert event.lock_name == "test_asyncio.py:35"
+    assert event.lock_name == "test_asyncio.py:38:lock"
     assert event.thread_id == _thread.get_ident()
     assert event.locked_for_ns >= 0
     # It's called through pytest so I'm sure it's gonna be that long, right?
@@ -61,7 +61,6 @@ async def test_lock_events_tracer(tracer):
             lock2 = asyncio.Lock()
             await lock2.acquire()
             lock.release()
-            trace_id = t.trace_id
             span_id = t.span_id
         lock2.release()
 
@@ -70,16 +69,23 @@ async def test_lock_events_tracer(tracer):
             pass
     events = r.reset()
     # The tracer might use locks, so we need to look into every event to assert we got ours
+    lock1_acquire, lock1_release, lock2_acquire, lock2_release = (
+        "test_asyncio.py:59:lock",
+        "test_asyncio.py:63:lock",
+        "test_asyncio.py:62:lock2",
+        "test_asyncio.py:65:lock2",
+    )
     for event_type in (collector_asyncio.AsyncioLockAcquireEvent, collector_asyncio.AsyncioLockReleaseEvent):
-        assert {"test_asyncio.py:58", "test_asyncio.py:61"}.issubset({e.lock_name for e in events[event_type]})
+        if event_type == collector_asyncio.AsyncioLockAcquireEvent:
+            assert {lock1_acquire, lock2_acquire}.issubset({e.lock_name for e in events[event_type]})
+        elif event_type == collector_asyncio.AsyncioLockReleaseEvent:
+            assert {lock1_release, lock2_release}.issubset({e.lock_name for e in events[event_type]})
         for event in events[event_type]:
-            if event.name == "test_asyncio.py:58":
-                assert event.trace_id is None
+            if event.lock_name in [lock1_acquire, lock2_release]:
                 assert event.span_id is None
                 assert event.trace_resource_container is None
                 assert event.trace_type is None
-            elif event.name == "test_asyncio.py:61":
-                assert event.trace_id == trace_id
+            elif event.lock_name in [lock2_acquire, lock1_release]:
                 assert event.span_id == span_id
                 assert event.trace_resource_container[0] == t.resource
                 assert event.trace_type == t.span_type