Restore trace callback when the profiler is disabled #334
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## main #334 +/- ##
===========================================
+ Coverage 63.78% 82.32% +18.53%
===========================================
Files 13 13
Lines 1041 1041
Branches 228 228
===========================================
+ Hits 664 857 +193
+ Misses 316 142 -174
+ Partials 61 42 -19 see 5 files with indirect coverage changes Continue to review full report in Codecov by Sentry.
🚀 New features to boost your workflow:
|
|
Because this modifies C code, it's going to take more time for me to carefully review. I think this will be independent of the other changes you were interested in working on, but let me know if any PR is a blocker for other features. The feature I'm most interested in right now, is the one where With all of these changes, I'm also starting to think it would be a good idea for me to spend some effort building regression tests that monitor the overhead of line profiler on benchmark use-cases. Right now I currently test it out and check that it doesn't feel sluggish, but that's not sustainable. |
|
Fair points, please take your time. Since we already have provisions for running "setup" code in |
TTsangSC
force-pushed
the
cooperative-tracing
branch
from
649750a to
0b393a4
Compare
line_profiler/_line_profiler.pyx
{fetch,restore}_c_trace_state()
New helper functions to help with caching the trace callback
call_c_trace_state_hook()
(FIXME: doesn't seem to work properly)
New helper function for calling the old trace callback from
within `python_trace_callback()`
LineProfiler
__init__()
New keyword argument `call_existing_trace` (and environment
variable `${LINE_PROFILER_CALL_EXISTING_TRACE}`) to control
whether `python_trace_callback()` should call the old trace
callback
enable(), disable()
Now managing a cache of the old trace callback, restoring it
when the profiler is disabled
call_existing_trace
New property corresponding to the synonymous argument
python_trace_callback()
Added conditional switch to call the old trace callback (FIXME)
tests/test_line_profiler.py::test_trace_callback_preservation()
New test that `sys.gettrace()` is restored after disabling the
profiler
line_profiler/_line_profiler.pyx
- Reordered definitions (fixes apparent namespacing issue with older
Pythons/Cythons)
- Removed unused references to `unset_trace()`
line_profiler/unset_trace.{c,h}
Removed due to being unused
line_profiler/_line_profiler.pyx
c_trace_state_has_hook(), get_optional_attr(), set_optional_attr()
New C-level helper functions
call_c_trace_state_hook_safe()
New Cython wrapper around `call_c_trace_state_hook()` which
guards against the following actions in the wrapped trace
callback which may hinder line profiling:
- (Un-)Setting the `sys` trace callback
- Setting `frame.f_trace`
- Setting `frame.f_trace_lines`
Notably, this allows `python_trace_callback()` to wrap around
`coverage.tracer.CTracer` without either stepping on the other's
toes
LineProfiler
- Extended docstring
- Renamed argument/attribute:
`call_existing_trace` -> `wrap_trace`
- Renamed environment variable from which the default value for
the above is read:
`LINE_PROFILER_CALL_EXISTING_TRACE`
-> `LINE_PROFILE_WRAP_TRACE`
python_trace_callback()
- Removed variables that are declared but unused
- Updated implementation to use `call_c_trace_state_hook_safe()`
instead of `call_c_trace_state_hook()`
line_profiler/_line_profiler.pyx
CTraceState
fetch_c_trace_state(), restore_c_trace_state()
c_trace_state_has_hook(), call_c_trace_state_hook()
get_optional_attr(), set_optional_attr()
Added documentation
call_c_trace_state_hook_safe()
No longer restoring `frame.f_trace`, which interferes with
`Python/sysmodule.c::trace_trampoline()` and prevents
Python-level trace functions from functioning for non-call
events
tests/test_line_profiler.py
test_trace_callback_preservation()
- Refactored to always be run in a subprocess and on a temporary
Python source file
- Updated the run Python source for more informative assertions
test_trace_callback_wrapping()
New test for using an existing trace callback in conjunction
with the profiler
tests/test_line_profiler.py::run_in_subproc()
Replaced `tempfile.NamedTemporaryFile()` with
`.TemporaryDirectory()` to circumvent double-open issues on Windows
line_profiler/_line_profiler.pyx
TraceCallback
Renamed from `CTraceState`
alloc_callback(), free_callback()
New functions for allocating `TraceCallback` objects
c_trace_state_has_hook()
Merged into `call_cached_callback()`
fetch_callback()
- Refactored and renamed from `fetch_c_trace_state()`
- No longer `malloc()`-ing and returning a pointer, instead
assigning to the fields of the pointer passed as the argument
restore_callback()
- Refactored and renamed from `restore_c_trace_state()`
- No longer `free()`-ing the supplied pointer, instead just
assigning `NULL` to its fields
call_callback()
- Merger of `call_c_trace_state_hook[_safe]()`
- Now staying entirely in C-land (where possible), avoiding
calling the `PyObject` attribute-access functions
- Refactored heap-allocated swap `TraceCallback` objects into
stack-allocated ones
- Added check for disabling of the `sys` trace function -- if
that happens, profiling continues (as with before) but the
wrapped/cached callback is no longer called
- Added check for disabling of frame-local line events -- if
that happens, `.f_trace_lines` is restored (as with before)
but the frame-local trace callable (`.f_trace`) is wrapped and
shielded from line events
get_optional_attr(), set_optional_attr()
Removed now-unused methods
disable_line_events()
New Python-level wrapper for shielding a frame-local trace
callable from line events
LineProfiler.wrap_trace
Cythonized definition
LineProfiler.{dis,en}able(), python_trace_callback()
Now handling per-thread caching of the `sys` callback state
tests/test_line_profiler.py
Moved tests that have to do with tracing to another test module
tests/test_sys_trace.py
New test module housing the test (and facilities therefor) for trace
function manipulations:
- isolate_test_in_subproc()
Refactored from `./test_line_profiler.py::run_in_subproc()`
into a decorator, which causes the wrapped test callable to be
called in a subprocess
- test_trace_callback_preservation(), test_trace_callback_wrapping()
Refactored from the synonymous tests in
`./test_line_profiler.py` so that:
- The test content is inside the function body instead of a
string literal
- The helper functions and classes are moved into the test
module's scope
- test_wrapping_throwing_callback()
test_wrapping_line_event_disabling_callback()
New tests for "problematic" callbacks that unset themselves or
attempt to disable line-profiling
line_profiler._line_profiler.pyx::call_callback()
- Fixed obscure bug occurring when the function tries to import the
`line_profiler._line_profiler` module object when `coverage.py`
tracing is on
- More verbose error messages because C code doesn't show up in
stack traces
tests/test_sys_trace.py
test_callback_preservation()
test_callback_wrapping()
test_wrapping_line_event_disabling_callback()
Minor stylistic updates
test_wrapping_thread_local_callbacks()
New test for wrapping around thread-local tracing functions in a
multithreaded environment
line_profiler/_line_profiler.pyx::alloc_callback()
Added missing handling for when `malloc()` fails
CHANGELOG.rst
Added entry
TTsangSC
force-pushed
the
cooperative-tracing
branch
from
0b393a4 to
edf2daa
Compare
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
(Closes #333.)
Summary
This draft PR adds C(-ython) level support to:
PyThreadState.c_tracefuncandPyThreadSatte.c_traceobj; note thatsys.gettrace()only gets the latter and misses the former, hence the need for C-level shenanigans) inLineProfiler.enable()LineProfiler.disable()wrap_traceargument and the${LINE_PROFILE_WRAP_TRACE}environment variable(UPDATE 17 Apr) It also adds 5 tests to the new test module
tests/test_sys_trace.py:test_callback_preservation():Checks the restoration of the trace-callback state after using the profiler.
test_callback_wrapping():Checks trace-callback interoperability – that the existing trace callback can be used by the profiler's callback.
test_wrapping_throwing_callback():Checks the continuation of line profiling and the disabling of the existing callback in the event that it errors out.
test_wrapping_line_event_disabling_callback():Checks the continuation of line profiling and the hiding of line events from the existing frame-local callback in the event that it disables frame line events.
test_wrapping_thread_local_callbacks():Checks the usage and restoration of thread-local existing trace callbacks by the profiler.
Since the trace-callback state is restored from the cached value in
.disable(), the now-unusedline_profiler/unset_trace.{c,h}and references thereto in build instructions and docs have also been removed.Motivation
As noted in #333,
LineProfilercurrently interacts destructively withsys.settrace(), setting it toNonewhen the profiler is.disable()-ed. Beside being in a way "not clean", this also has multiple unfortunate side effects, such as prohibiting cooperative use with other trace-callback based monitoring tools, such as coverage tools and debuggers.Notably, the discarding of the trace callback is what has been tanking the coverage that
codecovreports, becausecoverage.pycan't see anything after any test callsLineProfiler.enable()in-process.Effects
(UPDATE 17 Apr: see "Performance impacts" for updated timings.)
Note the substantial increase in coverages in
line_profiler.pyandprofiler_mixin.py:line_profiler.pyprofiler_mixin.pymainLINE_PROFILE_WRAP_TRACE=1Sample output (`main`; click to expand)
Sample output (this PR; click to expand)
Sample output (this PR w/ trace-callback wrapping; click to expand)
Caveats
(UPDATE 17 Apr: the optimizations mentioned below have been made.)
As shown by the test-suite output above, this PR may introduce some overhead to the tracing function. However:
Running the entire test suite without
pytest-covshows the following results:mainLINE_PROFILE_WRAP_TRACE=1Hence, in the case where we aren't interacting with other tracing facilities, the overhead is negligible and well within normal variations. Still, it may be worth looking into optimizing
wrap_trace(as implemented inline_profiler/_line_profiler.pyx::call_c_trace_state_hook_safe()) since that seem to have more severe performance implications. Since it mostly deals with objects available on the C-level (CTraceState,PyFrameObject.f_trace_lines,PyFrameObject.f_trace), it's likely that we can eke out more performance by movingcall_c_trace_state_hook_safe()from Cython to C – or just merge it with the C-levelcall_c_trace_state_hook()function which it calls.Update 17 Apr
Reorganization
The tests which have to do with
systrace callbacks have been moved from thetests/test_line_profiler.pymodule to the newtests/test_sys_trace.py.Handling of edge cases
In order for trace-callback wrapping to be more transparent (i.e. for the wrapped callback to behave more as if it was free-standing):
syscallback, either via erroring out or explicitly callingsys.settrace(None)(or its C equivalent). If a wrapped callback does so, e.g. incoverage.py::coverage/ctracer/tracer.c::CTracer_dealloc()(L87)):syscallback is restored so that profiling continues, as was previously done in this PR; but.disable()-ed, it unsets thesystrace callback instead of restoring it to the (dropped) cached value..f_trace_linesto false in a frame, disabling line events for the frame (which obstructs further line profiling). If a wrapped callback does so; e.g. incoverage.py::coverage/ctracer/tracer.c::CTracer_handle_call()(L548)):.f_trace_linesis reset so that profiling continues, as was previously done in this PR; but.f_traceis wrapped so that it is no longer invoked for line events.Moreover, support for multithreaded environments (where each thread can have its own
systrace function) has been added.Performance impacts
The previous timing info in "Effects" was unduly biased against the PR in that:
mainand PR branches had different dependency versions (e.g.pytest); updating them to be consistent substantially closed the gap.systrace callback, they have to be run in subprocesses to isolate their side effects, resulting in relatively higher overhead.As such, the venv dependencies have been updated to be consistent (
pytest==8.3.5,pytest-cov==6.1.1,coverage==7.8.0), and we now runrun_test.pyorpytestwith-k 'not sys_trace'to deselect the new tests. The updated timings are:With
pytest-cov(run_tests.py -k 'not sys_trace')Without
pytest-cov(pytest -k 'not sys_trace')mainLINE_PROFILE_WRAP_TRACE=1mainLINE_PROFILE_WRAP_TRACE=1Hence the overhead introduced by the PR seems negligible. (The coverage improvements remain the same as in "Effects" above.)