From 016beab783901f81720e2e793e31c9f73436b6c6 Mon Sep 17 00:00:00 2001 From: Taegyun Kim Date: Mon, 5 Aug 2024 20:46:45 -0400 Subject: [PATCH] fix(profiling): show lock init location and hide internal frame (#9692) [backport-2.10] (#10063) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Manual backport of #9692 to 2.10 Screenshot 2024-07-01 at 9 32 45 PM - Lock Name shows the line number of where `acquire/release/__enter__/__exit__` was called, which is duplicated in the Call Stack - Call Stack shows a frame for Profiler internal function, [\_\_enter\_\_](https://github.com/DataDog/dd-trace-py/blob/42ccea9b13e232bcce4a1d20b9d11eda7904226d/ddtrace/profiling/collector/_lock.py#L235) Screenshot 2024-07-01 at 9 27 35 PM - Lock Name shows the line number where the lock was initialized. - Call Stack shows user codes only. This actually reverts some of the changes I made in https://github.com/DataDog/dd-trace-py/pull/9615, but I believe this PR makes everything clearer. ## Checklist - [x] Change(s) are motivated and described in the PR description - [x] Testing strategy is described if automated tests are not included in the PR - [x] Risks are described (performance impact, potential for breakage, maintainability) - [x] Change is maintainable (easy to change, telemetry, documentation) - [x] [Library release note guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html) are followed or label `changelog/no-changelog` is set - [x] Documentation is included (in-code, generated user docs, [public corp docs](https://github.com/DataDog/documentation/)) - [x] Backport labels are set (if [applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)) - [x] If this PR changes the public interface, I've notified `@DataDog/apm-tees`. ## Reviewer Checklist - [x] Title is accurate - [x] All changes are related to the pull request's stated goal - [x] Description motivates each change - [x] Avoids breaking [API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces) changes - [x] Testing strategy adequately addresses listed risks - [x] Change is maintainable (easy to change, telemetry, documentation) - [x] Release note makes sense to a user of the library - [x] Author has acknowledged and discussed the performance implications of this PR as reported in the benchmarks PR comment - [x] Backport labels are set in a manner that is consistent with the [release branch maintenance policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting) (cherry picked from commit 97969ee7d3870854e6638574397e386586783b0a) --- ddtrace/profiling/collector/_lock.py | 40 +-- ...-init-loc-and-frames-39a43f924bde88d2.yaml | 5 + tests/profiling/collector/test_asyncio.py | 40 +-- tests/profiling/collector/test_threading.py | 249 +++++++++++------- .../collector/test_threading_asyncio.py | 4 +- tests/profiling/simple_program_fork.py | 24 +- 6 files changed, 210 insertions(+), 152 deletions(-) create mode 100644 releasenotes/notes/profiling-timeline-lock-init-loc-and-frames-39a43f924bde88d2.yaml diff --git a/ddtrace/profiling/collector/_lock.py b/ddtrace/profiling/collector/_lock.py index 1503baf0bd1..43476dd8faa 100644 --- a/ddtrace/profiling/collector/_lock.py +++ b/ddtrace/profiling/collector/_lock.py @@ -112,10 +112,13 @@ 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 + self._maybe_update_self_name() + lock_name = "%s:%s" % (self._self_init_loc, self._self_name) if self._self_name else self._self_init_loc if task_frame is None: - frame = sys._getframe(1) + # If we can't get the task frame, we use the caller frame. We expect acquire/release or + # __enter__/__exit__ to be on the stack, so we go back 2 frames. + frame = sys._getframe(2) else: frame = task_frame @@ -172,10 +175,13 @@ 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 + lock_name = ( + "%s:%s" % (self._self_init_loc, self._self_name) if self._self_name else self._self_init_loc + ) if task_frame is None: - frame = sys._getframe(1) + # See the comments in _acquire + frame = sys._getframe(2) else: frame = task_frame @@ -237,23 +243,23 @@ 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 + def _find_self_name(self, var_dict: typing.Dict): 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 + return name 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 + return attribute + return None # 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]: + def _maybe_update_self_name(self): + if self._self_name: + return try: # We expect the call stack to be like this: # 0: this @@ -268,24 +274,18 @@ def _get_lock_call_loc_with_name(self) -> typing.Optional[str]: if frame.f_code.co_name not in {"acquire", "release", "__enter__", "__exit__"}: raise AssertionError("Unexpected frame %s" % frame.f_code.co_name) frame = sys._getframe(3) - 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) + self._self_name = self._find_self_name(frame.f_locals) or self._find_self_name(frame.f_globals) - if self._self_name: - return "%s:%s" % (call_loc, self._self_name) - else: + if not self._self_name: + self._self_name = "" 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): diff --git a/releasenotes/notes/profiling-timeline-lock-init-loc-and-frames-39a43f924bde88d2.yaml b/releasenotes/notes/profiling-timeline-lock-init-loc-and-frames-39a43f924bde88d2.yaml new file mode 100644 index 00000000000..2edfc627289 --- /dev/null +++ b/releasenotes/notes/profiling-timeline-lock-init-loc-and-frames-39a43f924bde88d2.yaml @@ -0,0 +1,5 @@ +--- +fixes: + - | + profiling: show lock init location in Lock Name and hide profiler internal + frames from Stack Frame in Timeline Details tab. diff --git a/tests/profiling/collector/test_asyncio.py b/tests/profiling/collector/test_asyncio.py index 63bcc2ee937..4488a79728c 100644 --- a/tests/profiling/collector/test_asyncio.py +++ b/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:16:lock" + assert event.lock_name == "test_asyncio.py:15: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:38:lock" + assert event.lock_name == "test_asyncio.py:35: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? @@ -69,23 +69,27 @@ 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", - ) + lock1_name = "test_asyncio.py:58:lock" + lock2_name = "test_asyncio.py:61:lock2" + lines_with_trace = [61, 63] + lines_without_trace = [59, 65] for event_type in (collector_asyncio.AsyncioLockAcquireEvent, collector_asyncio.AsyncioLockReleaseEvent): if event_type == collector_asyncio.AsyncioLockAcquireEvent: - assert {lock1_acquire, lock2_acquire}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.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]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) for event in events[event_type]: - 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.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 + if event.name in [lock1_name, lock2_name]: + file_name, lineno, function_name, class_name = event.frames[0] + assert file_name == __file__.replace(".pyc", ".py") + assert lineno in lines_with_trace + lines_without_trace + assert function_name == "test_lock_events_tracer" + assert class_name == "" + if lineno in lines_without_trace: + assert event.span_id is None + assert event.trace_resource_container is None + assert event.trace_type is None + elif lineno in lines_with_trace: + assert event.span_id == span_id + assert event.trace_resource_container[0] == resource + assert event.trace_type == span_type diff --git a/tests/profiling/collector/test_threading.py b/tests/profiling/collector/test_threading.py index 61c01797858..4165053fe26 100644 --- a/tests/profiling/collector/test_threading.py +++ b/tests/profiling/collector/test_threading.py @@ -70,13 +70,13 @@ def test_lock_acquire_events(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 0 event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert event.lock_name == "test_threading.py:69:lock" + assert event.lock_name == "test_threading.py:68: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? assert len(event.frames) > 3 assert event.nframes > 3 - assert event.frames[1] == (__file__.replace(".pyc", ".py"), 69, "test_lock_acquire_events", "") + assert event.frames[0] == (__file__.replace(".pyc", ".py"), 69, "test_lock_acquire_events", "") assert event.sampling_pct == 100 @@ -94,13 +94,13 @@ def lockfunc(self): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 0 event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert event.lock_name == "test_threading.py:90:lock" + assert event.lock_name == "test_threading.py:89: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? assert len(event.frames) > 3 assert event.nframes > 3 - assert event.frames[1] == (__file__.replace(".pyc", ".py"), 90, "lockfunc", "Foobar") + assert event.frames[0] == (__file__.replace(".pyc", ".py"), 90, "lockfunc", "Foobar") assert event.sampling_pct == 100 @@ -118,27 +118,31 @@ def test_lock_events_tracer(tracer): span_id = t.span_id lock2.release() events = r.reset() - lock1_acquire, lock1_release, lock2_acquire, lock2_release = ( - "test_threading.py:113:lock", - "test_threading.py:117:lock", - "test_threading.py:116:lock2", - "test_threading.py:119:lock2", - ) + lock1_name = "test_threading.py:112:lock" + lock2_name = "test_threading.py:115:lock2" + lines_with_trace = [116, 117] + lines_without_trace = [113, 119] # The tracer might use locks, so we need to look into every event to assert we got ours for event_type in (collector_threading.ThreadingLockAcquireEvent, collector_threading.ThreadingLockReleaseEvent): if event_type == collector_threading.ThreadingLockAcquireEvent: - assert {lock1_acquire, lock2_acquire}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) elif event_type == collector_threading.ThreadingLockReleaseEvent: - assert {lock1_release, lock2_release}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) for event in events[event_type]: - 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.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 + if event.name in [lock1_name, lock2_name]: + file_name, lineno, function_name, class_name = event.frames[0] + assert file_name == __file__.replace(".pyc", ".py") + assert lineno in lines_with_trace + lines_without_trace + assert function_name == "test_lock_events_tracer" + assert class_name == "" + if lineno in lines_without_trace: + assert event.span_id is None + assert event.trace_resource_container is None + assert event.trace_type is None + elif lineno in lines_with_trace: + assert event.span_id == span_id + assert event.trace_resource_container[0] == resource + assert event.trace_type == span_type def test_lock_events_tracer_late_finish(tracer): @@ -156,18 +160,14 @@ def test_lock_events_tracer_late_finish(tracer): span.resource = resource span.finish() events = r.reset() - lock1_acquire, lock1_release, lock2_acquire, lock2_release = ( - "test_threading.py:150:lock", - "test_threading.py:154:lock", - "test_threading.py:153:lock2", - "test_threading.py:155:lock2", - ) + lock1_name = "test_threading.py:153:lock" + lock2_name = "test_threading.py:156:lock2" # The tracer might use locks, so we need to look into every event to assert we got ours for event_type in (collector_threading.ThreadingLockAcquireEvent, collector_threading.ThreadingLockReleaseEvent): if event_type == collector_threading.ThreadingLockAcquireEvent: - assert {lock1_acquire, lock2_acquire}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) elif event_type == collector_threading.ThreadingLockReleaseEvent: - assert {lock1_release, lock2_release}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) for event in events[event_type]: assert event.span_id is None assert event.trace_resource_container is None @@ -189,27 +189,31 @@ def test_resource_not_collected(monkeypatch, tracer): span_id = t.span_id lock2.release() events = r.reset() - lock1_acquire, lock1_release, lock2_acquire, lock2_release = ( - "test_threading.py:184:lock", - "test_threading.py:188:lock", - "test_threading.py:187:lock2", - "test_threading.py:190:lock2", - ) + lock1_name = "test_threading.py:183:lock" + lock2_name = "test_threading.py:186:lock2" + lines_with_trace = [187, 188] + lines_without_trace = [184, 190] # The tracer might use locks, so we need to look into every event to assert we got ours for event_type in (collector_threading.ThreadingLockAcquireEvent, collector_threading.ThreadingLockReleaseEvent): if event_type == collector_threading.ThreadingLockAcquireEvent: - assert {lock1_acquire, lock2_acquire}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) elif event_type == collector_threading.ThreadingLockReleaseEvent: - assert {lock1_release, lock2_release}.issubset({e.lock_name for e in events[event_type]}) + assert {lock1_name, lock2_name}.issubset({e.lock_name for e in events[event_type]}) for event in events[event_type]: - 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.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 + if event.name in [lock1_name, lock2_name]: + file_name, lineno, function_name, class_name = event.frames[0] + assert file_name == __file__.replace(".pyc", ".py") + assert lineno in lines_with_trace + lines_without_trace + assert function_name == "test_resource_not_collected" + assert class_name == "" + if lineno in lines_without_trace: + assert event.span_id is None + assert event.trace_resource_container is None + assert event.trace_type is None + elif lineno in lines_with_trace: + assert event.span_id == span_id + assert event.trace_resource_container[0] == resource + assert event.trace_type == span_type def test_lock_release_events(): @@ -221,13 +225,13 @@ def test_lock_release_events(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 event = r.events[collector_threading.ThreadingLockReleaseEvent][0] - assert event.lock_name == "test_threading.py:220:lock" + assert event.lock_name == "test_threading.py:222: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? assert len(event.frames) > 3 assert event.nframes > 3 - assert event.frames[1] == (__file__.replace(".pyc", ".py"), 220, "test_lock_release_events", "") + assert event.frames[0] == (__file__.replace(".pyc", ".py"), 224, "test_lock_release_events", "") assert event.sampling_pct == 100 @@ -261,16 +265,16 @@ def play_with_lock(): assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) >= 1 for event in r.events[collector_threading.ThreadingLockAcquireEvent]: - if event.lock_name == "test_threading.py:252:lock": + if event.lock_name == "test_threading.py:255:lock": assert event.wait_time_ns >= 0 assert event.task_id == t.ident assert event.task_name == "foobar" # 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[1] == ( + assert event.frames[0] == ( "tests/profiling/collector/test_threading.py", - 252, + 256, "play_with_lock", "", ), event.frames @@ -280,16 +284,16 @@ def play_with_lock(): pytest.fail("Lock event not found") for event in r.events[collector_threading.ThreadingLockReleaseEvent]: - if event.lock_name == "test_threading.py:253:lock": + if event.lock_name == "test_threading.py:255:lock": assert event.locked_for_ns >= 0 assert event.task_id == t.ident assert event.task_name == "foobar" # 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[1] == ( + assert event.frames[0] == ( "tests/profiling/collector/test_threading.py", - 253, + 257, "play_with_lock", "", ), event.frames @@ -387,32 +391,23 @@ def test_lock_enter_exit_events(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert acquire_event.lock_name == "test_threading.py:385:th_lock" + assert acquire_event.lock_name == "test_threading.py:388:th_lock" assert acquire_event.thread_id == _thread.get_ident() assert acquire_event.wait_time_ns >= 0 # We know that at least __enter__, this function, and pytest should be # in the stack. assert len(acquire_event.frames) >= 3 assert acquire_event.nframes >= 3 - # To implement 'with lock:', _lock._ProfiledLock implements __enter__ and - # __exit__. So frames[0] is __enter__ and __exit__ respectively. - - assert acquire_event.frames[0] == ( - _lock.__file__.replace(".pyc", ".py"), - 235, - "__enter__", - "_ProfiledThreadingLock", - ) - assert acquire_event.frames[1] == (__file__.replace(".pyc", ".py"), 385, "test_lock_enter_exit_events", "") + + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 389, "test_lock_enter_exit_events", "") assert acquire_event.sampling_pct == 100 release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] - release_lineno = 385 if sys.version_info >= (3, 10) else 386 - assert release_event.lock_name == "test_threading.py:%d:th_lock" % release_lineno + assert release_event.lock_name == "test_threading.py:388:th_lock" assert release_event.thread_id == _thread.get_ident() assert release_event.locked_for_ns >= 0 - assert release_event.frames[0] == (_lock.__file__.replace(".pyc", ".py"), 238, "__exit__", "_ProfiledThreadingLock") - assert release_event.frames[1] == ( + release_lineno = 389 if sys.version_info >= (3, 10) else 390 + assert release_event.frames[0] == ( __file__.replace(".pyc", ".py"), release_lineno, "test_lock_enter_exit_events", @@ -449,12 +444,14 @@ def test_class_member_lock(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 2 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 2 - acquire_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockAcquireEvent]} - assert acquire_lock_names == {"test_threading.py:429:foo_lock"} - - release_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockReleaseEvent]} - release_lienno = 429 if sys.version_info >= (3, 10) else 430 - assert release_lock_names == {"test_threading.py:%d:foo_lock" % release_lienno} + expected_lock_name = "test_threading.py:421:foo_lock" + for e in r.events[collector_threading.ThreadingLockAcquireEvent]: + assert e.lock_name == expected_lock_name + assert e.frames[0] == (__file__.replace(".pyc", ".py"), 424, "foo", "Foo") + for e in r.events[collector_threading.ThreadingLockReleaseEvent]: + assert e.lock_name == expected_lock_name + release_lineno = 424 if sys.version_info >= (3, 10) else 425 + assert e.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "foo", "Foo") def test_class_member_lock_no_inspect_dir(): @@ -465,11 +462,14 @@ def test_class_member_lock_no_inspect_dir(): bar.bar() assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 + expected_lock_name = "test_threading.py:421" acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert acquire_event.lock_name == "test_threading.py:429" + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 424, "foo", "Foo") release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] - release_lineno = 429 if sys.version_info >= (3, 10) else 430 - assert release_event.lock_name == "test_threading.py:%d" % release_lineno + assert release_event.lock_name == expected_lock_name + release_lineno = 424 if sys.version_info >= (3, 10) else 425 + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "foo", "Foo") def test_private_lock(): @@ -488,12 +488,14 @@ def foo(self): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 - + expected_lock_name = "test_threading.py:478:_Foo__lock" acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert acquire_event.lock_name == "test_threading.py:481:_Foo__lock" + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 481, "foo", "Foo") release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] + assert release_event.lock_name == expected_lock_name release_lineno = 481 if sys.version_info >= (3, 10) else 482 - assert release_event.lock_name == "test_threading.py:%d:_Foo__lock" % release_lineno + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "foo", "Foo") def test_inner_lock(): @@ -512,13 +514,14 @@ def bar(self): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 - - acquire_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockAcquireEvent]} - assert acquire_lock_names == {"test_threading.py:505"} - - release_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockReleaseEvent]} - release_lienno = 505 if sys.version_info >= (3, 10) else 506 - assert release_lock_names == {"test_threading.py:%d" % release_lienno} + expected_lock_name = "test_threading.py:421" + acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 507, "bar", "Bar") + release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] + assert release_event.lock_name == expected_lock_name + release_lineno = 507 if sys.version_info >= (3, 10) else 508 + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "bar", "Bar") def test_anonymous_lock(): @@ -529,12 +532,54 @@ def test_anonymous_lock(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 + expected_lock_name = "test_threading.py:530" + acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 530, "test_anonymous_lock", "") + release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] + assert release_event.lock_name == expected_lock_name + release_lineno = 530 if sys.version_info >= (3, 10) else 531 + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "test_anonymous_lock", "") + + +@pytest.mark.skipif(not os.getenv("WRAPT_DISABLE_EXTENSIONS"), reason="wrapt C extension is disabled") +def test_wrapt_c_ext_false(): + assert _lock.WRAPT_C_EXT is False + r = recorder.Recorder() + with collector_threading.ThreadingLockCollector(r, capture_pct=100): + th_lock = threading.Lock() + with th_lock: + pass + expected_lock_name = "test_threading.py:550:th_lock" + assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 + acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 551, "test_wrapt_c_ext_false", "") + assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 + release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] + assert release_event.lock_name == expected_lock_name + release_lineno = 551 if sys.version_info >= (3, 10) else 552 + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "test_wrapt_c_ext_false", "") + +@pytest.mark.skipif(os.getenv("WRAPT_DISABLE_EXTENSIONS"), reason="wrapt C extension is enabled") +def test_wrapt_c_ext_true(): + assert _lock.WRAPT_C_EXT is True + r = recorder.Recorder() + with collector_threading.ThreadingLockCollector(r, capture_pct=100): + th_lock = threading.Lock() + with th_lock: + pass + expected_lock_name = "test_threading.py:570:th_lock" + assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 1 acquire_event = r.events[collector_threading.ThreadingLockAcquireEvent][0] - assert acquire_event.lock_name == "test_threading.py:527" + assert acquire_event.lock_name == expected_lock_name + assert acquire_event.frames[0] == (__file__.replace(".pyc", ".py"), 571, "test_wrapt_c_ext_true", "") + assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 1 release_event = r.events[collector_threading.ThreadingLockReleaseEvent][0] - release_lineno = 527 if sys.version_info >= (3, 10) else 528 - assert release_event.lock_name == "test_threading.py:%d" % release_lineno + assert release_event.lock_name == expected_lock_name + release_lineno = 571 if sys.version_info >= (3, 10) else 572 + assert release_event.frames[0] == (__file__.replace(".pyc", ".py"), release_lineno, "test_wrapt_c_ext_true", "") def test_global_locks(): @@ -547,13 +592,19 @@ def test_global_locks(): assert len(r.events[collector_threading.ThreadingLockAcquireEvent]) == 2 assert len(r.events[collector_threading.ThreadingLockReleaseEvent]) == 2 - - acquire_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockAcquireEvent]} - assert acquire_lock_names == {"global_locks.py:9:global_lock", "global_locks.py:18:bar_lock"} - - release_lock_names = {e.lock_name for e in r.events[collector_threading.ThreadingLockReleaseEvent]} - release_lines = (9, 18) if sys.version_info >= (3, 10) else (10, 19) - assert release_lock_names == { - "global_locks.py:%d:global_lock" % release_lines[0], - "global_locks.py:%d:bar_lock" % release_lines[1], - } + expected_lock_names = ["global_locks.py:4:global_lock", "global_locks.py:15:bar_lock"] + expected_filename = __file__.replace(".pyc", ".py").replace("test_threading", "global_locks") + for e in r.events[collector_threading.ThreadingLockAcquireEvent]: + assert e.lock_name in expected_lock_names + if e.lock_name == expected_lock_names[0]: + assert e.frames[0] == (expected_filename, 9, "foo", "") + elif e.lock_name == expected_lock_names[1]: + assert e.frames[0] == (expected_filename, 18, "bar", "Bar") + for e in r.events[collector_threading.ThreadingLockReleaseEvent]: + assert e.lock_name in expected_lock_names + if e.lock_name == expected_lock_names[0]: + release_lineno = 9 if sys.version_info >= (3, 10) else 10 + assert e.frames[0] == (expected_filename, release_lineno, "foo", "") + elif e.lock_name == expected_lock_names[1]: + release_lineno = 18 if sys.version_info >= (3, 10) else 19 + assert e.frames[0] == (expected_filename, release_lineno, "bar", "Bar") diff --git a/tests/profiling/collector/test_threading_asyncio.py b/tests/profiling/collector/test_threading_asyncio.py index fa38411c42d..a91c5d7156f 100644 --- a/tests/profiling/collector/test_threading_asyncio.py +++ b/tests/profiling/collector/test_threading_asyncio.py @@ -32,10 +32,10 @@ def asyncio_run(): lock_found = 0 for event in events[collector_threading.ThreadingLockAcquireEvent]: - if event.lock_name == "test_threading_asyncio.py:17:lock": + if event.lock_name == "test_threading_asyncio.py:16:lock": assert event.task_name.startswith("Task-") lock_found += 1 - elif event.lock_name == "test_threading_asyncio.py:21:lock": + elif event.lock_name == "test_threading_asyncio.py:20:lock": assert event.task_name is None assert event.thread_name == "foobar" lock_found += 1 diff --git a/tests/profiling/simple_program_fork.py b/tests/profiling/simple_program_fork.py index db3f004dbba..5671e0904b0 100644 --- a/tests/profiling/simple_program_fork.py +++ b/tests/profiling/simple_program_fork.py @@ -12,7 +12,7 @@ lock = threading.Lock() lock.acquire() -lock_acquire_name = "simple_program_fork.py:14:lock" +lock_lock_name = "simple_program_fork.py:13:lock" assert ddtrace.profiling.bootstrap.profiler.status == service.ServiceStatus.RUNNING @@ -30,24 +30,23 @@ lock.release() # We don't track it - assert lock_acquire_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) # We track this one though lock = threading.Lock() - lock_acquire_name = "simple_program_fork.py:39:lock" - assert lock_acquire_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockAcquireEvent]) + lock_lock_name = "simple_program_fork.py:36:lock" + assert lock_lock_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockAcquireEvent]) lock.acquire() events = recorder.reset() - assert lock_acquire_name in set(e.lock_name for e in events[cthreading.ThreadingLockAcquireEvent]) - lock_release_name = "simple_program_fork.py:44:lock" - assert lock_release_name not in set(e.lock_name for e in events[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name in set(e.lock_name for e in events[cthreading.ThreadingLockAcquireEvent]) + assert lock_lock_name not in set(e.lock_name for e in events[cthreading.ThreadingLockReleaseEvent]) lock.release() - assert lock_release_name in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) parent_events = parent_recorder.reset() # Let's sure our copy of the parent recorder does not receive it since the parent profiler has been stopped - assert lock_acquire_name not in set(e.lock_name for e in parent_events[cthreading.ThreadingLockAcquireEvent]) - assert lock_release_name not in set(e.lock_name for e in parent_events[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name not in set(e.lock_name for e in parent_events[cthreading.ThreadingLockAcquireEvent]) + assert lock_lock_name not in set(e.lock_name for e in parent_events[cthreading.ThreadingLockReleaseEvent]) # This can run forever if anything is broken! while not recorder.events[stack_event.StackSampleEvent]: @@ -55,10 +54,9 @@ else: recorder = ddtrace.profiling.bootstrap.profiler._profiler._recorder assert recorder is parent_recorder - lock_release_name = "simple_program_fork.py:60:lock" - assert lock_release_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name not in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) lock.release() - assert lock_release_name in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) + assert lock_lock_name in set(e.lock_name for e in recorder.reset()[cthreading.ThreadingLockReleaseEvent]) assert ddtrace.profiling.bootstrap.profiler.status == service.ServiceStatus.RUNNING print(child_pid) pid, status = os.waitpid(child_pid, 0)