diff --git a/CHANGELOG.rst b/CHANGELOG.rst index effad2e6..457ae496 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -16,6 +16,7 @@ Changes * ENH: Highlight final summary using rich if enabled * ENH: Made it possible to use multiple profiler instances simultaneously * ENH: various improvements related to auto-profiling: + * ``kernprof -p`` target entities are now imported and profiled regardless of whether they are directly imported in the run script/module/code (old behavior restored by passing ``--no-preimports``) @@ -25,7 +26,23 @@ Changes like class methods and properties * ``LineProfiler`` can now be used as a class decorator * FIX: Fixed line tracing for Cython code; superseded use of the legacy tracing system with ``sys.monitoring`` -* ENH: Fixed edge case where :py:meth:`LineProfiler.get_stats()` neglects data from duplicate code objects (#348) +* FIX: Fixed edge cases where: + + * ``LineProfiler.get_stats()`` neglected data from duplicate code objects + (#348) + * ``LineProfiler`` instances may stop receiving tracing events when multiple + instances were used (#350) + * Line events were not reported for ``raise`` statements and ``finally:`` + bodies when using ``sys.monitoring`` (#355) +* FIX: Tracing-system-related fixes (#333): + + * ``LineProfiler`` now caches the existing ``sys`` or ``sys.monitoring`` trace + callbacks in ``.enable()`` and restores them in ``.disable()``, instead of + always discarding them on the way out + * Also added experimental support for calling (instead of suspending) said + callbacks during profiling + * Now allowing switching back to the "legacy" trace system on Python 3.12+, + controlled by an environment variable 4.2.0 ~~~~~ diff --git a/docs/source/auto/line_profiler._line_profiler.rst b/docs/source/auto/line_profiler._line_profiler.rst index d7f02731..2fe20242 100644 --- a/docs/source/auto/line_profiler._line_profiler.rst +++ b/docs/source/auto/line_profiler._line_profiler.rst @@ -2,6 +2,7 @@ line\_profiler.\_line\_profiler module ====================================== .. automodule:: line_profiler._line_profiler + :private-members: _LineProfilerManager :members: :undoc-members: :show-inheritance: diff --git a/docs/source/conf.py b/docs/source/conf.py index b9d11285..eb8f30b2 100644 --- a/docs/source/conf.py +++ b/docs/source/conf.py @@ -194,6 +194,9 @@ def visit_Assign(self, node): 'geowatch.tasks.cold.export_change_map', ] +autodoc_default_options = { # Document callable classes + 'special-members': '__call__'} + autodoc_member_order = 'bysource' autoclass_content = 'both' # autodoc_mock_imports = ['torch', 'torchvision', 'visdom'] diff --git a/line_profiler/CMakeLists.txt b/line_profiler/CMakeLists.txt index 6f0e0844..1eefdbf0 100644 --- a/line_profiler/CMakeLists.txt +++ b/line_profiler/CMakeLists.txt @@ -10,6 +10,7 @@ add_cython_target(${module_name} "${cython_source}" C OUTPUT_VAR sources) # Add any other non-cython dependencies to the sources list(APPEND sources "${CMAKE_CURRENT_SOURCE_DIR}/timers.c" + "${CMAKE_CURRENT_SOURCE_DIR}/c_trace_callbacks.c" ) message(STATUS "[OURS] sources = ${sources}") diff --git a/line_profiler/Python_wrapper.h b/line_profiler/Python_wrapper.h new file mode 100644 index 00000000..88bf1537 --- /dev/null +++ b/line_profiler/Python_wrapper.h @@ -0,0 +1,96 @@ +// Compatibility layer over `Python.h`. + +#ifndef LINE_PROFILER_PYTHON_WRAPPER_H +#define LINE_PROFILER_PYTHON_WRAPPER_H + +#include "Python.h" + +// Ensure PyFrameObject availability as a concretely declared struct + +// _frame -> PyFrameObject +#if PY_VERSION_HEX >= 0x030b00a6 // 3.11.0a6 +# ifndef Py_BUILD_CORE +# define Py_BUILD_CORE 1 +# endif +# include "internal/pycore_frame.h" +# include "cpython/code.h" +# include "pyframe.h" +#else +# include "frameobject.h" +#endif + +// Backport of Python 3.9 caller hooks + +#if PY_VERSION_HEX < 0x030900a4 // 3.9.0a4 +# define PyObject_CallOneArg(func, arg) \ + PyObject_CallFunctionObjArgs(func, arg, NULL) +# define PyObject_CallMethodOneArg(obj, name, arg) \ + PyObject_CallMethodObjArgs(obj, name, arg, NULL) +# define PyObject_CallNoArgs(func) \ + PyObject_CallFunctionObjArgs(func, NULL) +# define PyObject_CallMethodNoArgs(obj, name) \ + PyObject_CallMethodObjArgs(obj, name, NULL) +#endif + +#if PY_VERSION_HEX < 0x030900a5 // 3.9.0a5 +# define PyThreadState_GetInterpreter(tstate) \ + ((tstate)->interp) +#endif + +#if PY_VERSION_HEX < 0x030900b1 // 3.9.0b1 + /* + * Notes: + * While 3.9.0a1 already has `PyFrame_GetCode()`, it doesn't + * INCREF the code object until 0b1 (PR #19773), so override + * that for consistency. + */ +# define PyFrame_GetCode(x) PyFrame_GetCode_backport(x) + inline PyCodeObject *PyFrame_GetCode_backport(PyFrameObject *frame) + { + PyCodeObject *code; + assert(frame != NULL); + code = frame->f_code; + assert(code != NULL); + Py_INCREF(code); + return code; + } +#endif + +#if PY_VERSION_HEX < 0x030b00b1 // 3.11.0b1 + /* + * Notes: + * Since 3.11.0a7 (PR #31888) `co_code` has been made a + * descriptor, so: + * - This already creates a NewRef, so don't INCREF in that + * case; and + * - `code->co_code` will not work. + */ + inline PyObject *PyCode_GetCode(PyCodeObject *code) + { + PyObject *code_bytes; + if (code == NULL) return NULL; +# if PY_VERSION_HEX < 0x030b00a7 // 3.11.0a7 + code_bytes = code->co_code; + Py_XINCREF(code_bytes); +# else + code_bytes = PyObject_GetAttrString(code, "co_code"); +# endif + return code_bytes; + } +#endif + +#if PY_VERSION_HEX < 0x030d00a1 // 3.13.0a1 + inline PyObject *PyImport_AddModuleRef(const char *name) + { + PyObject *mod = NULL, *name_str = NULL; + name_str = PyUnicode_FromString(name); + if (name_str == NULL) goto cleanup; + mod = PyImport_AddModuleObject(name_str); + Py_XINCREF(mod); + cleanup: + Py_XDECREF(name_str); + return mod; + } +#endif + +#endif // LINE_PROFILER_PYTHON_WRAPPER_H diff --git a/line_profiler/_diagnostics.py b/line_profiler/_diagnostics.py index 8ef2cc68..cbf3d24b 100644 --- a/line_profiler/_diagnostics.py +++ b/line_profiler/_diagnostics.py @@ -2,26 +2,102 @@ Global state initialized at import time. Used for hidden arguments and developer features. """ -from line_profiler import _logger import os +import sys +from types import ModuleType +from line_profiler import _logger -def _boolean_environ(key): - """ +def _boolean_environ( + envvar, + truey=frozenset({'1', 'on', 'true', 'yes'}), + falsy=frozenset({'0', 'off', 'false', 'no'}), + default=False): + r""" Args: - key (str) + envvar (str) + Name for the environment variable to read from. + truey (Collection[str]) + Values to be considered truey. + falsy (Collection[str]) + Values to be considered falsy. + default (bool) + Default boolean value to resolve to. Returns: - bool + :py:data:`True` + If the (case-normalized) environment variable is equal to + any of ``truey``. + :py:data:`False` + If the (case-normalized) environment variable is equal to + any of ``falsy``. + ``default`` + Otherwise. + + Example: + >>> from os import environ + >>> from subprocess import run + >>> from sys import executable + >>> from textwrap import dedent + >>> + >>> + >>> def resolve_in_subproc(value, default, + ... envvar='MY_ENVVAR', + ... truey=('foo',), falsy=('bar',)): + ... code = dedent(''' + ... from {0.__module__} import {0.__name__} + ... print({0.__name__}({1!r}, {2!r}, {3!r}, {4!r})) + ... ''').strip('\n').format(_boolean_environ, envvar, + ... tuple(truey), tuple(falsy), + ... bool(default)) + ... env = environ.copy() + ... env[envvar] = value + ... proc = run([executable, '-c', code], + ... capture_output=True, env=env, text=True) + ... proc.check_returncode() + ... return {'True': True, + ... 'False': False}[proc.stdout.strip()] + ... + >>> + >>> # Truey value + >>> assert resolve_in_subproc('FOO', True) == True + >>> assert resolve_in_subproc('FOO', False) == True + >>> # Falsy value + >>> assert resolve_in_subproc('BaR', True) == False + >>> assert resolve_in_subproc('BaR', False) == False + >>> # Mismatch -> fall back to default + >>> assert resolve_in_subproc('baz', True) == True + >>> assert resolve_in_subproc('baz', False) == False """ - value = os.environ.get(key, '').lower() - TRUTHY_ENVIRONS = {'true', 'on', 'yes', '1'} - return value in TRUTHY_ENVIRONS + # (TODO: migrate to `line_profiler.cli_utils.boolean()` after + # merging #335) + try: + value = os.environ.get(envvar).casefold() + except AttributeError: # None + return default + non_default_values = falsy if default else truey + if value in {v.casefold() for v in non_default_values}: + return not default + return default +# `kernprof` switches DEBUG = _boolean_environ('LINE_PROFILER_DEBUG') NO_EXEC = _boolean_environ('LINE_PROFILER_NO_EXEC') KEEP_TEMPDIRS = _boolean_environ('LINE_PROFILER_KEEP_TEMPDIRS') STATIC_ANALYSIS = _boolean_environ('LINE_PROFILER_STATIC_ANALYSIS') +# `line_profiler._line_profiler` switches +WRAP_TRACE = _boolean_environ('LINE_PROFILER_WRAP_TRACE') +SET_FRAME_LOCAL_TRACE = _boolean_environ('LINE_PROFILER_SET_FRAME_LOCAL_TRACE') +_MUST_USE_LEGACY_TRACE = not isinstance( + getattr(sys, 'monitoring', None), ModuleType) +USE_LEGACY_TRACE = ( + _MUST_USE_LEGACY_TRACE + or _boolean_environ('LINE_PROFILER_CORE', + # Also provide `coverage-style` aliases + truey={'old', 'legacy', 'ctrace'}, + falsy={'new', 'sys.monitoring', 'sysmon'}, + default=_MUST_USE_LEGACY_TRACE)) + log = _logger.Logger('line_profiler', backend='auto') diff --git a/line_profiler/_line_profiler.pyx b/line_profiler/_line_profiler.pyx index faaee8e0..edafc601 100644 --- a/line_profiler/_line_profiler.pyx +++ b/line_profiler/_line_profiler.pyx @@ -13,7 +13,8 @@ Ignore: ./line_profiler/_line_profiler.pyx \ ./line_profiler/timers.c """ -from .python25 cimport PyFrameObject, PyObject, PyStringObject +from collections.abc import Callable +from functools import wraps from sys import byteorder import sys cimport cython @@ -26,8 +27,13 @@ import threading import opcode import os import types +from warnings import warn from weakref import WeakSet +from line_profiler._diagnostics import ( + WRAP_TRACE, SET_FRAME_LOCAL_TRACE, USE_LEGACY_TRACE) + + NOP_VALUE: int = opcode.opmap['NOP'] # The Op code should be 2 bytes as stated in @@ -39,92 +45,70 @@ NOP_BYTES: bytes = NOP_VALUE.to_bytes(NOP_BYTES_LEN, byteorder=byteorder) # This should be true for Python >=3.11a1 HAS_CO_QUALNAME: bool = hasattr(types.CodeType, 'co_qualname') -# "Lightweight" monitoring in 3.12.0b1+ -CAN_USE_SYS_MONITORING = PY_VERSION_HEX >= 0x030c00b1 - -# Can't line-trace Cython in 3.12 -# (TODO: write monitoring hook, Cython function line events are emitted -# only via `sys.monitoring` and are invisible to the "legacy" tracing -# system) +# Can't line-profile Cython in 3.12 since the old C API was upended +# without an appropriate replacement (which only came in 3.13); +# see also: +# https://cython.readthedocs.io/en/latest/src/tutorial/profiling_tutorial.html +_CAN_USE_SYS_MONITORING = PY_VERSION_HEX >= 0x030c00b1 CANNOT_LINE_TRACE_CYTHON = ( - CAN_USE_SYS_MONITORING and PY_VERSION_HEX < 0x030d00b1) + _CAN_USE_SYS_MONITORING and PY_VERSION_HEX < 0x030d00b1) + +if not (USE_LEGACY_TRACE or _CAN_USE_SYS_MONITORING): + # Shouldn't happen since we're already checking the existence of + # `sys.monitoring` in `line_profiler._diagnostics`, but just to be + # absolutely sure... + warn("`sys.monitoring`-based line profiling selected but unavailable " + f"in Python {sys.version}; falling back to the legacy trace system") + USE_LEGACY_TRACE = True # long long int is at least 64 bytes assuming c99 ctypedef unsigned long long int uint64 ctypedef long long int int64 -# FIXME: there might be something special we have to do here for Python 3.11 -cdef extern from "frameobject.h": - """ - #if PY_VERSION_HEX < 0x030900b1 // 3.9.0b1 - /* - * Notes: - * While 3.9.0a1 already has `PyFrame_GetCode()`, it doesn't - * INCREF the code object until 0b1 (PR #19773), so override - * that for consistency. - */ - inline PyCodeObject *get_frame_code( - PyFrameObject *frame - ) { - PyCodeObject *code; - assert(frame != NULL); - code = frame->f_code; - assert(code != NULL); - Py_INCREF(code); - return code; - } - #else - #define get_frame_code(x) PyFrame_GetCode(x) - #endif - """ +cdef extern from "Python_wrapper.h": + ctypedef struct PyObject ctypedef struct PyCodeObject - cdef PyCodeObject* get_frame_code(PyFrameObject* frame) - ctypedef int (*Py_tracefunc)(object self, PyFrameObject *py_frame, int what, PyObject *arg) - -cdef extern from "Python.h": - """ - // CPython 3.11 broke some stuff by moving PyFrameObject :( - #if PY_VERSION_HEX >= 0x030b00a6 - #ifndef Py_BUILD_CORE - #define Py_BUILD_CORE 1 - #endif - #include "internal/pycore_frame.h" - #include "cpython/code.h" - #include "pyframe.h" - #endif - """ ctypedef struct PyFrameObject ctypedef long long PY_LONG_LONG - cdef bint PyCFunction_Check(object obj) + ctypedef int (*Py_tracefunc)( + object self, PyFrameObject *py_frame, int what, PyObject *arg) + + cdef PyCodeObject* PyFrame_GetCode(PyFrameObject* frame) cdef int PyCode_Addr2Line(PyCodeObject *co, int byte_offset) - cdef void PyEval_SetProfile(Py_tracefunc func, object arg) cdef void PyEval_SetTrace(Py_tracefunc func, object arg) - - ctypedef object (*PyCFunction)(object self, object args) - - ctypedef struct PyMethodDef: - char *ml_name - PyCFunction ml_meth - int ml_flags - char *ml_doc - - ctypedef struct PyCFunctionObject: - PyMethodDef *m_ml - PyObject *m_self - PyObject *m_module + cdef PyObject* PyObject_Call( + PyObject *callable, PyObject *args, PyObject *kwargs) except * # They're actually #defines, but whatever. cdef int PyTrace_CALL cdef int PyTrace_EXCEPTION cdef int PyTrace_LINE cdef int PyTrace_RETURN + cdef int PyTrace_OPCODE cdef int PyTrace_C_CALL cdef int PyTrace_C_EXCEPTION cdef int PyTrace_C_RETURN cdef int PyFrame_GetLineNumber(PyFrameObject *frame) +cdef extern from "c_trace_callbacks.c": # Legacy tracing + ctypedef unsigned long long Py_uintptr_t + + ctypedef struct TraceCallback: + Py_tracefunc c_tracefunc + PyObject *c_traceobj + + cdef TraceCallback *alloc_callback() except * + cdef void free_callback(TraceCallback *callback) + cdef void populate_callback(TraceCallback *callback) + cdef void restore_callback(TraceCallback *callback) + cdef int call_callback( + PyObject *disabler, TraceCallback *callback, + PyFrameObject *py_frame, int what, PyObject *arg) + cdef void set_local_trace(PyObject *manager, PyFrameObject *py_frame) + cdef Py_uintptr_t monitoring_restart_version() + cdef extern from "timers.c": PY_LONG_LONG hpTimer() double hpTimerUnit() @@ -157,7 +141,7 @@ cdef inline object multibyte_rstrip(bytes bytecode): Returns: result (tuple[bytes, int]) - First item is the bare unpadded bytecode - - Second item is the number of :py:const:`NOP_BYTES` + - Second item is the number of :py:data:`NOP_BYTES` ``bytecode`` has been padded with """ npad: int = 0 @@ -170,70 +154,35 @@ cdef inline object multibyte_rstrip(bytes bytecode): return (unpadded, npad) -if CAN_USE_SYS_MONITORING: - def _is_main_thread() -> bool: - return threading.current_thread() == threading.main_thread() - - def _sys_monitoring_register(instances) -> None: - # Note: only activating `sys.monitoring` line events for the - # profiled code objects in `LineProfiler.add_function()` may - # seem like an obvious optimization, but: - # - That adds complexity and muddies the logic, because - # `.set_local_events()` can only be called if the tool id is - # in use (e.g. activated via `.use_tool_id()`), and - # - That doesn't result in much (< 2%) performance improvement - # in tests - if not _is_main_thread(): - return - mon = sys.monitoring - mon.use_tool_id(mon.PROFILER_ID, 'line_profiler') - # Activate line events - events = (mon.get_events(mon.PROFILER_ID) - | mon.events.LINE - | mon.events.PY_RETURN - | mon.events.PY_YIELD - | mon.events.RAISE - | mon.events.RERAISE) - mon.set_events(mon.PROFILER_ID, events) - # TODO: store and/or call previous callbacks, see #334 - line_callback = functools.partial( - monitoring_line_event_callback, instances) - exit_callback = functools.partial( - monitoring_exit_frame_callback, instances) - mon.register_callback(mon.PROFILER_ID, mon.events.LINE, line_callback) - mon.register_callback( - mon.PROFILER_ID, mon.events.PY_RETURN, exit_callback) - mon.register_callback( - mon.PROFILER_ID, mon.events.PY_YIELD, exit_callback) - mon.register_callback( - mon.PROFILER_ID, mon.events.RAISE, exit_callback) - mon.register_callback( - mon.PROFILER_ID, mon.events.RERAISE, exit_callback) - - def _sys_monitoring_deregister() -> None: - if not _is_main_thread(): - return - mon = sys.monitoring - mon.free_tool_id(mon.PROFILER_ID) - mon.register_callback(mon.PROFILER_ID, mon.events.LINE, None) - mon.register_callback(mon.PROFILER_ID, mon.events.PY_RETURN, None) - mon.register_callback(mon.PROFILER_ID, mon.events.PY_YIELD, None) - mon.register_callback(mon.PROFILER_ID, mon.events.RAISE, None) - mon.register_callback(mon.PROFILER_ID, mon.events.RERAISE, None) +cdef inline object get_current_callback(int tool_id, int event_id): + """ + Note: + Unfortunately there's no public API for directly retrieving + the current callback, no matter on the Python side or the C + side. This may become a performance bottleneck... + """ + mon = sys.monitoring + cdef object register = mon.register_callback + cdef object result = register(tool_id, event_id, None) + if result is not None: + register(tool_id, event_id, result) + return result def label(code): """ - Return a (filename, first_lineno, _name) tuple for a given code object. + Return a ``(filename, first_lineno, _name)`` tuple for a given code + object. - This is the similar labelling as used by the cProfile module in Python 2.5. + This is the similar labelling as used by the :py:mod:`cProfile` + module in Python 2.5. Note: - In Python >=3.11 we use we return qualname for _name. + In Python >= 3.11 we return qualname for ``_name``. In older versions of Python we just return name. """ if isinstance(code, str): - return ('~', 0, code) # built-in functions ('~' sorts at the end) + return ('~', 0, code) # built-in functions ('~' sorts at the end) else: if HAS_CO_QUALNAME: return (code.co_filename, code.co_firstlineno, code.co_qualname) @@ -247,7 +196,7 @@ def find_cython_source_file(cython_func): Returns: result (str | None) - Cython source file if found, else :py:const:`None`. + Cython source file if found, else :py:data:`None`. """ try: compiled_module = cython_func.__globals__['__file__'] @@ -269,9 +218,41 @@ def find_cython_source_file(cython_func): prefix = next_prefix +def disable_line_events(trace_func: Callable) -> Callable: + """ + Returns: + trace_func (Callable) + If it is a wrapper created by + :py:attr:`_LineProfilerManager.wrap_local_f_trace`; + ``trace_func.disable_line_events`` is also set to true + wrapper (Callable) + Otherwise, a thin wrapper around ``trace_func()`` which + withholds line events. + + Note: + This is for when a frame-local :py:attr:`~frame.f_trace` + disables :py:attr:`~frame.f_trace_lines` -- we would like to + keep line events enabled (so that line profiling works) while + "unsubscribing" the trace function from it. + """ + @wraps(trace_func) + def wrapper(frame, event, arg): + if event == 'line': + return + return trace_func(frame, event, arg) + + try: # Disable the wrapper directly + if hasattr(trace_func, '__line_profiler_manager__'): + trace_func.disable_line_events = True + return trace_func + except AttributeError: + pass + return wrapper + + cpdef _code_replace(func, co_code): """ - Implements CodeType.replace for Python < 3.8 + Implements :py:mod:`~code.replace` for Python < 3.8 """ try: code = func.__code__ @@ -292,6 +273,24 @@ cpdef _code_replace(func, co_code): return code +cpdef int _patch_events(int events, int before, int after): + """ + Patch ``events`` based on the differences between ``before`` and + ``after``. + + Example: + >>> events = 0b110000 + >>> before = 0b101101 + >>> after = 0b_001011 # Additions: 0b10, deletions: 0b100100 + >>> assert _patch_events(events, before, after) == 0b010010 + """ + cdef int all_set_bits, plus, minus + all_set_bits = before | after + plus = all_set_bits - before + minus = all_set_bits - after + return ((events | minus) - minus) | plus + + # Note: this is a regular Python class to allow easy pickling. class LineStats(object): """ @@ -299,11 +298,13 @@ class LineStats(object): Attributes: - timings (dict): - Mapping from (filename, first_lineno, function_name) of the - profiled function to a list of (lineno, nhits, total_time) tuples - for each profiled line. total_time is an integer in the native - units of the timer. + timings (dict[tuple[str, int, str], \ +list[tuple[int, int, int]]]): + Mapping from ``(filename, first_lineno, function_name)`` of + the profiled function to a list of + ``(lineno, nhits, total_time)`` tuples for each profiled + line. ``total_time`` is an integer in the native units of + the timer. unit (float): The number of seconds per timer unit. @@ -313,12 +314,547 @@ class LineStats(object): self.unit = unit +cdef class _SysMonitoringState: + """ + Another helper object for managing the thread-local state. + + Note: + Documentations are for reference only, and all APIs are to be + considered private and subject to change. + """ + cdef int tool_id + cdef object name # type: str | None + # type: dict[int, Callable | None], int = event id + cdef dict callbacks + # type: dict[int, set[tuple[code, Unpack[tuple]]]], + # int = event id, tuple = + cdef dict disabled + cdef int events + cdef Py_uintptr_t restart_version + + if _CAN_USE_SYS_MONITORING: + line_tracing_event_set = ( # type: ClassVar[FrozenSet[int]] + frozenset({sys.monitoring.events.LINE, + sys.monitoring.events.PY_RETURN, + sys.monitoring.events.PY_YIELD, + sys.monitoring.events.RAISE, + sys.monitoring.events.RERAISE})) + line_tracing_events = (sys.monitoring.events.LINE + | sys.monitoring.events.PY_RETURN + | sys.monitoring.events.PY_YIELD + | sys.monitoring.events.RAISE + | sys.monitoring.events.RERAISE) + else: + line_tracing_event_set = frozenset({}) + line_tracing_events = 0 + + def __init__(self, tool_id: int): + self.tool_id = tool_id + self.name = None + self.callbacks = {} + self.disabled = {} + self.events = 0 # NO_EVENTS + self.restart_version = monitoring_restart_version() + + cpdef register(self, object handle_line, + object handle_return, object handle_yield, + object handle_raise, object handle_reraise): + # Note: only activating `sys.monitoring` line events for the + # profiled code objects in `LineProfiler.add_function()` may + # seem like an obvious optimization, but: + # - That adds complexity and muddies the logic, because + # `.set_local_events()` can only be called if the tool id is + # in use (e.g. activated via `.use_tool_id()`), and + # - That doesn't result in much (< 2%) performance improvement + # in tests + mon = sys.monitoring + + # Set prior state + self.name = mon.get_tool(self.tool_id) + if self.name is None: + self.events = mon.events.NO_EVENTS + else: + self.events = mon.get_events(self.tool_id) + mon.free_tool_id(self.tool_id) + mon.use_tool_id(self.tool_id, 'line_profiler') + mon.set_events(self.tool_id, self.events | self.line_tracing_events) + + # Register tracebacks + for event_id, callback in [ + (mon.events.LINE, handle_line), + (mon.events.PY_RETURN, handle_return), + (mon.events.PY_YIELD, handle_yield), + (mon.events.RAISE, handle_raise), + (mon.events.RERAISE, handle_reraise)]: + self.callbacks[event_id] = mon.register_callback( + self.tool_id, event_id, callback) + + cpdef deregister(self): + mon = sys.monitoring + cdef dict wrapped_callbacks = self.callbacks + + # Restore prior state + mon.free_tool_id(self.tool_id) + if self.name is not None: + mon.use_tool_id(self.tool_id, self.name) + mon.set_events(self.tool_id, self.events) + self.name = None + self.events = mon.events.NO_EVENTS + + # Reset tracebacks + while wrapped_callbacks: + mon.register_callback(self.tool_id, *wrapped_callbacks.popitem()) + + cdef void call_callback(self, int event_id, object code, + object loc_args, object other_args): + """ + Call the appropriate stored callback. Also take care of the + restoration of :py:mod:`sys.monitoring` callbacks, tool-ID lock, + and events should they be unset. + + Note: + * This is deliberately made a non-traceable C method so that + we don't fall info infinite recursion. + * ``loc_args`` and ``other_args`` should be tuples. + """ + mon = sys.monitoring + cdef PyObject *result + cdef object callback # type: Callable | None + cdef object callback_after # type: Callable | None + cdef object code_location # type: tuple[code, Unpack[tuple]] + cdef object arg_tuple # type: tuple[code, Unpack[tuple]] + cdef object disabled # type: set[tuple[code, Unpack[tuple]]] + cdef int ev_id, events_before + cdef Py_uintptr_t version = monitoring_restart_version() + cdef dict callbacks_before = {} + + # If we've restarted events, clear the `.disabled` registry + if version != self.restart_version: + self.restart_version = version + self.disabled.clear() + + # Call the wrapped callback where suitable + callback = self.callbacks.get(event_id) + if callback is None: # No cached callback + return + code_location = (code,) + loc_args + disabled = self.disabled.setdefault(event_id, set()) + if code_location in disabled: # Events 'disabled' for the loc + return + if not (self.events # Callback should not receive the event + | mon.get_local_events(self.tool_id, code)) & event_id: + return + + for ev_id in self.line_tracing_event_set: + callbacks_before[ev_id] = get_current_callback(self.tool_id, ev_id) + + arg_tuple = code_location + other_args + try: + events_before = mon.get_events(self.tool_id) + result = PyObject_Call( + callback, arg_tuple, NULL) + else: + # Since we can't actually disable the event (or line + # profiling will be interrupted), just mark the location so + # that we stop calling the cached callback until the next + # time `sys.monitoring.restart_events()` is called + if result == (mon.DISABLE): + disabled.add(code_location) + finally: + # Update the events + self.events = _patch_events( + self.events, events_before, mon.get_events(self.tool_id)) + # If the wrapped callback has changed: + register = mon.register_callback + for ev_id, callback in callbacks_before.items(): + # - Restore the `sys.monitoring` callback + callback_after = register(self.tool_id, ev_id, callback) + # - Remember the updated callback in `self.callbacks` + if callback is not callback_after: + self.callbacks[ev_id] = callback_after + # Reset the tool ID lock if released + if not mon.get_tool(self.tool_id): + mon.use_tool_id(self.tool_id, 'line_profiler') + # Restore the `sys.monitoring` events if unset + mon.set_events(self.tool_id, + self.events | self.line_tracing_events) + + +cdef class _LineProfilerManager: + """ + Helper object for managing the thread-local state. + Supports being called with the same signature as a legacy trace + function (see :py:func:`sys.settrace`). + + Other methods of interest: + + :py:meth:`~.handle_line_event` + Callback for |LINE|_ events + :py:meth:`~.handle_return_event` + Callback for |PY_RETURN|_ events + :py:meth:`~.handle_yield_event` + Callback for |PY_YIELD|_ events + :py:meth:`~.handle_raise_event` + Callback for |RAISE|_ events + :py:meth:`~.handle_reraise_event` + Callback for |RERAISE|_ events + + Note: + Documentations are for reference only, and all APIs are to be + considered private and subject to change. + + .. |LINE| replace:: :py:attr:`!sys.monitoring.events.LINE` + .. |PY_RETURN| replace:: :py:attr:`!sys.monitoring.events.PY_RETURN` + .. |PY_YIELD| replace:: :py:attr:`!sys.monitoring.events.PY_YIELD` + .. |RAISE| replace:: :py:attr:`!sys.monitoring.events.RAISE` + .. |RERAISE| replace:: :py:attr:`!sys.monitoring.events.RERAISE` + .. _LINE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-LINE + .. _PY_RETURN: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-PY_RETURN + .. _PY_YIELD: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-PY_YIELD + .. _RAISE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-RAISE + .. _RERAISE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-RERAISE + """ + cdef TraceCallback *legacy_callback + cdef _SysMonitoringState mon_state + cdef public object active_instances # type: set[LineProfiler] + cdef int _wrap_trace + cdef int _set_frame_local_trace + cdef int recursion_guard + + def __init__( + self, tool_id: int, wrap_trace: bool, set_frame_local_trace: bool): + """ + Arguments: + tool_id (int) + Tool ID for use with :py:mod:`sys.monitoring`. + wrap_trace (bool) + Whether to wrap around legacy and + :py:mod:`sys.monitoring` trace functions and call them. + set_frame_local_trace (bool) + If using the legacy trace system, whether to insert the + instance as a frame's :py:attr:`~frame.f_trace` upon + entering a function scope. + + See also: + :py:class:`~.LineProfiler` + """ + self.legacy_callback = NULL + self.mon_state = _SysMonitoringState(tool_id) + + self.active_instances = set() + self.wrap_trace = wrap_trace + self.set_frame_local_trace = set_frame_local_trace + self.recursion_guard = 0 + + @cython.profile(False) + def __call__(self, frame: types.FrameType, event: str, arg): + """ + Calls |legacy_trace_callback|_. If :py:func:`sys.gettrace` + returns this instance, replaces the default C-level trace + function |trace_trampoline|_ with |legacy_trace_callback|_ to + reduce overhead. + + Returns: + self (_LineProfilerManager): + This instance. + + .. |legacy_trace_callback| replace:: \ +:c:func:`!legacy_trace_callback` + .. |trace_trampoline| replace:: :c:func:`!trace_trampoline` + .. _legacy_trace_callback: https://github.com/pyutils/\ +line_profiler/blob/main/line_profiler/_line_profiler.pyx + .. _trace_trampoline: https://github.com/python/cpython/blob/\ +6cb20a219a860eaf687b2d968b41c480c7461909/Python/sysmodule.c#L1124 + """ + cdef int what = {'call': PyTrace_CALL, + 'exception': PyTrace_EXCEPTION, + 'line': PyTrace_LINE, + 'return': PyTrace_RETURN, + 'opcode': PyTrace_OPCODE}[event] + if not self.recursion_guard: + # Prevent recursion (e.g. when `.wrap_trace` and + # `.set_frame_local_trace` are both true) + legacy_trace_callback(self, frame, + what, arg) + # Set the C-level trace callback back to + # `legacy_trace_callback()` where appropriate, so that future + # calls can bypass this `.__call__()` method + if sys.gettrace() is self: + PyEval_SetTrace(legacy_trace_callback, self) + return self + + def wrap_local_f_trace(self, trace_func: Callable) -> Callable: + """ + Arguments: + trace_func (Callable[[frame, str, Any], Any]) + Frame-local trace function, presumably set by another + global trace function. + + Returns: + wrapper (Callable[[frame, str, Any], Any]) + Thin wrapper around ``trace_func()`` which calls it, + calls the instance, then returns the return value of + ``trace_func()``. This helps prevent other frame-local + trace functions from displacing the instance when its + :py:attr:`~.set_frame_local_trace` is true. + + Note: + * The ``.__line_profiler_manager__`` attribute of the + returned wrapper is set to the instance. + * Line events are not passed to the wrapped callable if + ``wrapper.disable_line_events`` is set to true. + """ + @wraps(trace_func) + def wrapper(frame, event, arg): + if wrapper.disable_line_events and event == 'line': + result = None + else: + result = trace_func(frame, event, arg) + self(frame, event, arg) + return result + + wrapper.__line_profiler_manager__ = self + wrapper.disable_line_events = False + try: # Unwrap the wrapper + if trace_func.__line_profiler_manager__ is self: + trace_func = trace_func.__wrapped__ + except AttributeError: + pass + return wrapper + + # If we allowed these `sys.monitoring` callbacks to be profiled + # (i.e. to emit line events), we may fall into an infinite recusion; + # so disable profiling for them pre-emptively + + @cython.profile(False) + cpdef handle_line_event(self, object code, int lineno): + """ + Line-event (|LINE|_) callback passed to + :py:func:`sys.monitoring.register_callback`. + + .. |LINE| replace:: :py:attr:`!sys.monitoring.events.LINE` + .. _LINE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-LINE + """ + self._base_callback( + 1, sys.monitoring.events.LINE, code, lineno, (lineno,), ()) + + @cython.profile(False) + cpdef handle_return_event( + self, object code, int instruction_offset, object retval): + """ + Return-event (|PY_RETURN|_) callback passed to + :py:func:`sys.monitoring.register_callback`. + + .. |PY_RETURN| replace:: \ +:py:attr:`!sys.monitoring.events.PY_RETURN` + .. _PY_RETURN: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-PY_RETURN + """ + self._handle_exit_event( + sys.monitoring.events.PY_RETURN, code, instruction_offset, retval) + + @cython.profile(False) + cpdef handle_yield_event( + self, object code, int instruction_offset, object retval): + """ + Yield-event (|PY_YIELD|_) callback passed to + :py:func:`sys.monitoring.register_callback`. + + .. |PY_YIELD| replace:: \ +:py:attr:`!sys.monitoring.events.PY_YIELD` + .. _PY_YIELD: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-PY_YIELD + """ + self._handle_exit_event( + sys.monitoring.events.PY_YIELD, code, instruction_offset, retval) + + @cython.profile(False) + cpdef handle_raise_event( + self, object code, int instruction_offset, object exception): + """ + Raise-event (|RAISE|_) callback passed to + :py:func:`sys.monitoring.register_callback`. + + .. |RAISE| replace:: :py:attr:`!sys.monitoring.events.RAISE` + .. _RAISE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-RAISE + """ + self._handle_exit_event( + sys.monitoring.events.RAISE, code, instruction_offset, exception) + + @cython.profile(False) + cpdef handle_reraise_event( + self, object code, int instruction_offset, object exception): + """ + Re-raise-event (|RERAISE|_) callback passed to + :py:func:`sys.monitoring.register_callback`. + + .. |RERAISE| replace:: :py:attr:`!sys.monitoring.events.RERAISE` + .. _RERAISE: https://docs.python.org/3/library/\ +sys.monitoring.html#monitoring-event-RERAISE + """ + self._handle_exit_event( + sys.monitoring.events.RERAISE, code, instruction_offset, exception) + + cdef void _handle_exit_event( + self, int event_id, object code, int offset, object obj): + """ + Base for the frame-exit-event (e.g. via returning or yielding) + callbacks passed to :py:func:`sys.monitoring.register_callback`. + + Note: + This is deliberately made a non-traceable C method so that + we don't fall info infinite recursion. + """ + cdef int lineno = PyCode_Addr2Line(code, offset) + self._base_callback(0, event_id, code, lineno, (offset,), (obj,)) + + cdef void _base_callback( + self, int is_line_event, int event_id, object code, int lineno, + object loc_args, object other_args): + """ + Base for the various callbacks passed to + :py:func:`sys.monitoring.register_callback`. + + Note: + * This is deliberately made a non-traceable C method so that + we don't fall info infinite recursion. + * ``loc_args`` and ``other_args`` should be tuples. + """ + inner_trace_callback( + is_line_event, self.active_instances, code, lineno) + if self._wrap_trace: + self.mon_state.call_callback(event_id, code, loc_args, other_args) + + cpdef _handle_enable_event(self, prof): + cdef TraceCallback* legacy_callback + instances = self.active_instances + already_active = bool(instances) + instances.add(prof) + if already_active: + return + if USE_LEGACY_TRACE: + legacy_callback = alloc_callback() + populate_callback(legacy_callback) + self.legacy_callback = legacy_callback + PyEval_SetTrace(legacy_trace_callback, self) + else: + self.mon_state.register(self.handle_line_event, + self.handle_return_event, + self.handle_yield_event, + self.handle_raise_event, + self.handle_reraise_event) + + cpdef _handle_disable_event(self, prof): + cdef TraceCallback* legacy_callback + instances = self.active_instances + instances.discard(prof) + if instances: + return + # Only use the legacy trace-callback system if Python < 3.12 or + # if explicitly requested with `LINE_PROFILER_CORE=legacy`; + # otherwise, use `sys.monitoring` + # see: https://docs.python.org/3/library/sys.monitoring.html + if USE_LEGACY_TRACE: + legacy_callback = self.legacy_callback + restore_callback(legacy_callback) + free_callback(legacy_callback) + self.legacy_callback = NULL + else: + self.mon_state.deregister() + + property wrap_trace: + def __get__(self): + return bool(self._wrap_trace) + def __set__(self, wrap_trace): + self._wrap_trace = 1 if wrap_trace else 0 + + property set_frame_local_trace: + def __get__(self): + return bool(self._set_frame_local_trace) + def __set__(self, set_frame_local_trace): + # Note: as noted in `LineProfiler.__doc__`, there is no + # point in tempering with `.f_trace` when using + # `sys.monitoring`... so just set it to false + self._set_frame_local_trace = ( + 1 if set_frame_local_trace and USE_LEGACY_TRACE else 0) + + cdef class LineProfiler: """ Time the execution of lines of Python code. This is the Cython base class for - :class:`line_profiler.line_profiler.LineProfiler`. + :py:class:`line_profiler.line_profiler.LineProfiler`. + + Arguments: + *functions (function) + Function objects to be profiled. + wrap_trace (bool | None) + What to do for existing :py:mod:`sys` trace callbacks when + an instance is :py:meth:`.enable`-ed: + + :py:data:`True`: + *Wrap around* said callbacks: when our profiling trace + callbacks run, they call the corresponding existing + callbacks (where applicable). + :py:data:`False`: + *Suspend* said callbacks as long as + :py:class:`LineProfiler` instances are enabled. + :py:data:`None` (default): + For the first instance created, resolves to + + :py:data:`True` + If the environment variable + :envvar:`LINE_PROFILER_WRAP_TRACE` is set to any of + ``{'1', 'on', 'true', 'yes'}`` (case-insensitive). + + :py:data:`False` + Otherwise. + + If other instances already exist, the value is inherited + therefrom. + + In any case, when all instances are :py:meth:`.disable`-ed, + the :py:mod:`sys` trace system is restored to the state from + when the first instance was :py:meth:`.enable`-ed. + See the :ref:`caveats ` and also the + :ref:`extra explanation `. + set_frame_local_trace (bool | None) + When using the + :ref:`"legacy" trace system `), what to do + when entering a function or code block (i.e. an event of + type :c:data:`PyTrace_CALL` or ``'call'`` is encountered) + when an instance is :py:meth:`.enable`-ed: + + :py:data:`True`: + Set the frame's :py:attr:`~frame.f_trace` to + an object associated with the profiler. + :py:data:`False`: + Don't do so. + :py:data:`None` (default): + For the first instance created, resolves to + + :py:data:`True` + If the environment variable + :envvar:`LINE_PROFILER_SET_FRAME_LOCAL_TRACE` is set + to any of ``{'1', 'on', 'true', 'yes'}`` + (case-insensitive). + + :py:data:`False` + Otherwise. + + If other instances already exist, the value is inherited + therefrom. + + See the :ref:`caveats ` and also the + :ref:`extra explanation `. Example: >>> import copy @@ -337,6 +873,133 @@ cdef class LineProfiler: >>> self.last_time >>> # Print stats >>> self.print_stats() + + .. _warning-trace-caveats: + + Warning: + * Setting :py:attr:`.wrap_trace` and/or + :py:attr:`.set_frame_local_trace` helps with using + :py:class:`LineProfiler` cooperatively with other tools, like + coverage and debugging tools, especially when using the + :ref:`"legacy" trace system `. However, these + parameters should be considered **experimental** and to be + used at one's own risk -- because tools generally assume that + they have sole control over system-wide tracing (if using + "legacy" tracing), or at least over the + :py:mod:`sys.monitoring` tool ID it acquired. + * When setting :py:attr:`.wrap_trace` and + :py:attr:`.set_frame_local_trace`, they are set process-wide + for all instances. + + .. _note-backends: + + Note: + There are two "cores"/"backends" for :py:class:`LineProfiler` + between which users can choose: + + ``'new'``, ``'sys.monitoring'``, or ``'sysmon'`` + Use :py:mod:`sys.monitoring` events and callbacks. Only + available on (and is the default for) Python 3.12 and newer. + ``'old'``, ``'legacy'``, or ``'ctrace'`` + Use the `"legacy" trace system`_ (:py:func:`sys.gettrace`, + :py:func:`sys.settrace`, and :c:func:`PyEval_SetTrace`). + Default for Python < 3.12. + + Where both cores are available, the user can choose between the + two by supplying a suitable value to the environment variable + :envvar:`LINE_PROFILER_CORE`. + + .. _note-wrap_trace: + + Note: + More on :py:attr:`.wrap_trace`: + + * In general, Python allows for trace callbacks to unset + themselves, either intentionally (via + ``sys.settrace(None)`` or + ``sys.monitoring.register_callback(..., None)``) or if they + error out. If the wrapped/cached trace callbacks do so, + profiling would continue, but: + + * The cached callbacks are cleared and are no longer called, + and + * The trace callbacks are unset when all profiler instances + are :py:meth:`.disable`-ed. + * If a wrapped/cached frame-local + :ref:`"legacy" trace callable ` + (:py:attr:`~frame.f_trace`) sets + :py:attr:`~frame.f_trace_lines` to false in a frame to + disable local line events, :py:attr:`~.frame.f_trace_lines` + is restored (so that profiling can continue), but said + callable will no longer receive said events. + * Likewise, wrapped/cached :py:mod:`sys.monitoring` callbacks + can also disable events: + + * At *specific code locations* by returning + :py:data:`sys.monitoring.DISABLE`; + * By calling :py:func:`sys.monitoring.set_events` and + changing the *global event set*; or + * By calling :py:func:`sys.monitoring.register_callback` and + *replacing itself* with alternative callbacks (or + :py:data:`None`). + + When that happens, said disabling acts are again suitably + intercepted so that line profiling continues, but: + + * Said callbacks will no longer receive the corresponding + events, and + * The :py:mod:`sys.monitoring` callbacks and event set are + updated correspondingly when all profiler instances are + :py:meth:`.disable`-ed. + + Note that: + + * As with when line profiling is not used, if + :py:func:`sys.monitoring.restart_events` is called, the list + of code locations where events are suppressed is cleared, + and the wrapped/cached callbacks will once again receive + events from the + previously-:py:data:`~sys.monitoring.DISABLE`-d locations. + * Callbacks which only listen to and alter code-object-local + events (via :py:func:`sys.monitoring.set_local_events`) do + not interfere with line profiling, and such changes are + therefore not intercepted. + + .. _note-set_frame_local_trace: + + Note: + More on :py:attr:`.set_frame_local_trace`: + + * Since frame-local trace functions is no longer a useful + concept in the new :py:mod:`sys.monitoring`-based system + (see also the :ref:`Note on "cores" `), the + parameter/attribute always resolves to :py:data:`False` when + using the new :py:class:`LineProfiler` core. + * With the :ref:`"legacy" trace system `, when + :py:class:`LineProfiler` instances are :py:meth:`.enable`-ed, + :py:func:`sys.gettrace` returns an object which manages + profiling on the thread between all active profiler instances. + Said object has the same call signature as callables that + :py:func:`sys.settrace` takes, so that pure-Python code which + temporarily overrides the trace callable (e.g. + :py:meth:`doctest.DocTestRunner.run`) can function with + profiling. After the object is restored with + :py:func:`sys.settrace` by said code: + + * If :py:attr:`set_frame_local_trace` is true, line + profiling resumes *immediately*, because the object has + already been set to the frame's :py:attr:`~frame.f_trace`. + * However, if :py:attr:`set_frame_local_trace` is false, + line profiling only resumes *upon entering another code + block* (e.g. by calling a callable), because trace + callables set via :py:func:`sys.settrace` is only called + for ``'call'`` events (see the `C implementation`_ of + :py:mod:`sys`). + + .. _C implementation: https://github.com/python/cpython/blob/\ +6cb20a219a860eaf687b2d968b41c480c7461909/Python/sysmodule.c#L1124 + .. _"legacy" trace system: https://github.com/python/cpython/blob/\ +3.13/Python/legacy_tracing.c """ cdef unordered_map[int64, unordered_map[int64, LineTime]] _c_code_map # Mapping between thread-id and map of LastTime @@ -347,14 +1010,24 @@ cdef class LineProfiler: cdef public object threaddata # These are shared between instances and threads - # type: dict[int, set[LineProfiler]], int = thread id - _all_active_instances = {} - # type: dict[bytes, int], bytes = bytecode + if _CAN_USE_SYS_MONITORING: + # Note: just in case we ever need to override this, e.g. for + # testing + tool_id = sys.monitoring.PROFILER_ID # type: ClassVar[int] + else: + # Note: the value doesn't matter here... but set it to be + # consistent (because the value is public API) + tool_id = 2 + # type: ClassVar[dict[int, _LineProfilerManager]], int = thread id + _managers = {} + # type: ClassVar[dict[bytes, int]], bytes = bytecode _all_paddings = {} - # type: dict[int, weakref.WeakSet[LineProfiler]], int = func id + # type: ClassVar[dict[int, weakref.WeakSet[LineProfiler]]], + # int = func id _all_instances_by_funcs = {} - def __init__(self, *functions): + def __init__(self, *functions, + wrap_trace=None, set_frame_local_trace=None): self.functions = [] self.code_hash_map = {} self.dupes_map = {} @@ -362,19 +1035,34 @@ cdef class LineProfiler: # Create a data store for thread-local objects # https://docs.python.org/3/library/threading.html#thread-local-data self.threaddata = threading.local() + if wrap_trace is not None: + self.wrap_trace = wrap_trace + if set_frame_local_trace is not None: + self.set_frame_local_trace = set_frame_local_trace for func in functions: self.add_function(func) cpdef add_function(self, func): - """ Record line profiling information for the given Python function. + """ + Record line profiling information for the given Python function. + + Note: + This is a low-level method and is intended for |function|_; + users should in general use + :py:meth:`line_profiler.LineProfiler.add_callable` for + adding general callables and callable wrappers (e.g. + :py:class:`property`). + + .. |function| replace:: :py:class:`types.FunctionType` + .. _function: https://docs.python.org/3/reference/\ +datamodel.html#user-defined-functions """ if hasattr(func, "__wrapped__"): - import warnings - warnings.warn( - "Adding a function with a __wrapped__ attribute. You may want " - "to profile the wrapped function by adding %s.__wrapped__ " - "instead." % (func.__name__,) + warn( + "Adding a function with a `.__wrapped__` attribute. " + "You may want to profile the wrapped function by adding " + f"`{func.__name__}.__wrapped__` instead." ) try: code = func.__code__ @@ -384,8 +1072,8 @@ cdef class LineProfiler: code = func.__func__.__code__ func_id = id(func.__func__) except AttributeError: - import warnings - warnings.warn("Could not extract a code object for the object %r" % (func,)) + warn( + f"Could not extract a code object for the object {func!r}") return # Note: if we are to alter the code object, other profilers @@ -494,15 +1182,53 @@ cdef class LineProfiler: def __set__(self, value): self.threaddata.enable_count = value - # This is shared between instances, but thread-local - property _active_instances: + # These three are shared between instances, but thread-local + # (Ideally speaking they could've been class attributes...) + + property wrap_trace: + def __get__(self): + return self._manager.wrap_trace + def __set__(self, wrap_trace): + # Make sure we have a manager + manager = self._manager + # Sync values between all thread states + for manager in self._managers.values(): + manager.wrap_trace = wrap_trace + + property set_frame_local_trace: + def __get__(self): + return self._manager.set_frame_local_trace + def __set__(self, set_frame_local_trace): + # Make sure we have a manager + manager = self._manager + # Sync values between all thread states + for manager in self._managers.values(): + manager.set_frame_local_trace = set_frame_local_trace + + property _manager: def __get__(self): thread_id = threading.get_ident() try: - return self._all_active_instances[thread_id] + return self._managers[thread_id] except KeyError: - insts = self._all_active_instances[thread_id] = set() - return insts + pass + # First profiler instance on the thread, get the correct + # `wrap_trace` and `set_frame_local_trace` values and set up + # a `_LineProfilerManager` + try: + manager, *_ = self._managers.values() + except ValueError: + # First thread in the interpretor: load default values + # from the environment (at package startup time) + wrap_trace = WRAP_TRACE + set_frame_local_trace = SET_FRAME_LOCAL_TRACE + else: + # Fetch the values from an existing manager + wrap_trace = manager.wrap_trace + set_frame_local_trace = manager.set_frame_local_trace + self._managers[thread_id] = manager = _LineProfilerManager( + self.tool_id, wrap_trace, set_frame_local_trace) + return manager def enable_by_count(self): """ Enable the profiler if it hasn't been enabled before. @@ -512,8 +1238,9 @@ cdef class LineProfiler: self.enable_count += 1 def disable_by_count(self): - """ Disable the profiler if the number of disable requests matches the - number of enable requests. + """ + Disable the profiler if the number of disable requests matches + (or exceeds) the number of enable requests. """ if self.enable_count > 0: self.enable_count -= 1 @@ -527,16 +1254,7 @@ cdef class LineProfiler: self.disable_by_count() def enable(self): - # Use `sys.monitoring` in Python 3.12 and above; - # otherwise, use the legacy trace-callback system - # see: https://docs.python.org/3/library/sys.monitoring.html - instances = self._active_instances - if not instances: - if CAN_USE_SYS_MONITORING: - _sys_monitoring_register(instances) - else: - PyEval_SetTrace(legacy_trace_callback, instances) - instances.add(self) + self._manager._handle_enable_event(self) @property def c_code_map(self): @@ -564,8 +1282,9 @@ cdef class LineProfiler: @property def code_map(self): """ - line_profiler 4.0 no longer directly maintains code_map, but this will - construct something similar for backwards compatibility. + :py:mod:`line_profiler` 4.0 no longer directly maintains + :py:attr:`~.code_map`, but this will construct something similar + for backwards compatibility. """ c_code_map = self.c_code_map code_hash_map = self.code_hash_map @@ -585,8 +1304,9 @@ cdef class LineProfiler: @property def last_time(self): """ - line_profiler 4.0 no longer directly maintains last_time, but this will - construct something similar for backwards compatibility. + :py:mod:`line_profiler` 4.0 no longer directly maintains + :py:attr:`~.last_time`, but this will construct something similar + for backwards compatibility. """ c_last_time = self.c_last_time py_last_time = {} @@ -596,24 +1316,14 @@ cdef class LineProfiler: py_last_time[code] = c_last_time[block_hash] return py_last_time - cpdef disable(self): - instances = self._active_instances self._c_last_time[threading.get_ident()].clear() - instances.discard(self) - # Use `sys.monitoring` in Python 3.12 and above; - # otherwise, use the legacy trace-callback system - # see: https://docs.python.org/3/library/sys.monitoring.html - if instances: - return - elif CAN_USE_SYS_MONITORING: - _sys_monitoring_deregister() - else: - PyEval_SetTrace(NULL, NULL) + self._manager._handle_disable_event(self) def get_stats(self): """ - Return a LineStats object containing the timings. + Returns: + :py:class:`LineStats` object containing the timings. """ cdef dict cmap = self._c_code_map @@ -680,41 +1390,25 @@ cdef inline inner_trace_callback( line_entries = prof._c_code_map[code_hash] key = old.f_lineno if not line_entries.count(key): - prof._c_code_map[code_hash][key] = LineTime(code_hash, key, 0, 0) + prof._c_code_map[code_hash][key] = LineTime( + code_hash, key, 0, 0) prof._c_code_map[code_hash][key].nhits += 1 prof._c_code_map[code_hash][key].total_time += time - old.time if is_line_event: - # Get the time again. This way, we don't record much time wasted - # in this function. + # Get the time again. This way, we don't record much time + # wasted in this function. prof._c_last_time[ident][block_hash] = LastTime(lineno, hpTimer()) elif prof._c_last_time[ident].count(block_hash): - # We are returning from a function, not executing a line. Delete - # the last_time record. It may have already been deleted if we - # are profiling a generator that is being pumped past its end. - prof._c_last_time[ident].erase(prof._c_last_time[ident].find(block_hash)) - - -def monitoring_line_event_callback(object instances, object code, int lineno): - """ - Base of the line-event callback passed to - :py:func:`sys.monitoring.register_callback`. - """ - inner_trace_callback(1, instances, code, lineno) - - -def monitoring_exit_frame_callback( - object instances, object code, int instruction_offset, object _): - """ - Base of the callback passed to - :py:func:`sys.monitoring.register_callback`, to be called when a - frame is exited (e.g. via returning or yielding). - """ - cdef int lineno = PyCode_Addr2Line(code, instruction_offset) - inner_trace_callback(0, instances, code, lineno) + # We are returning from a function, not executing a line. + # Delete the last_time record. It may have already been + # deleted if we are profiling a generator that is being + # pumped past its end. + prof._c_last_time[ident].erase( + prof._c_last_time[ident].find(block_hash)) cdef extern int legacy_trace_callback( - object instances, PyFrameObject *py_frame, int what, PyObject *arg): + object manager, PyFrameObject *py_frame, int what, PyObject *arg): """ The :c:func:`PyEval_SetTrace` callback. @@ -722,11 +1416,58 @@ cdef extern int legacy_trace_callback( https://github.com/python/cpython/blob/de2a4036/Include/cpython/\ pystate.h#L16 """ - if what == PyTrace_LINE or what == PyTrace_RETURN: + cdef _LineProfilerManager manager_ = <_LineProfilerManager>manager + cdef int result + cdef int recursion_guard = manager_.recursion_guard + + if what == PyTrace_CALL: + # Any code using the `sys.gettrace()`-`sys.settrace()` paradigm + # (e.g. to temporarily suspend or alter tracing) will cause line + # events to not be passed to the global trace callback (i.e. + # `manager`) for the rest of the frame, e.g. + # >>> callback = sys.gettrace() + # >>> sys.settrace(None) + # >>> try: # Tracing suspended here + # ... ... + # ... finally: + # ... # Tracing object restored here, but line event + # ... # tracing is disabled before the next function + # ... # call because that's what the default trace + # ... # trampoline works + # ... sys.settrace(callback) + # To circumvent this, set the local `.f_trace` upon entering a + # frame (if not already set), so that tracing can restart upon + # the restoration with `sys.settrace()` + if manager_._set_frame_local_trace: + set_local_trace(manager_, py_frame) + elif what == PyTrace_LINE or what == PyTrace_RETURN: # Normally we'd need to DECREF the return from - # `get_frame_code()`, but Cython does that for us + # `PyFrame_GetCode()`, but Cython does that for us inner_trace_callback((what == PyTrace_LINE), - instances, - get_frame_code(py_frame), + manager_.active_instances, + PyFrame_GetCode(py_frame), PyFrame_GetLineNumber(py_frame)) - return 0 + + # Call the trace callback that we're wrapping around where + # appropriate + if manager_._wrap_trace: + # Due to how the frame-local callback could be set to the active + # `_LineProfilerManager` or a wrapper object (see + # `set_local_trace()`), wrap the callback call to make sure that + # we don't recurse back here + manager_.recursion_guard = 1 + try: + result = call_callback( + disable_line_events, manager_.legacy_callback, + py_frame, what, arg) + finally: + manager_.recursion_guard = recursion_guard + else: + result = 0 + + # Prevent other trace functions from overwritting `manager`; + # if there is a frame-local trace function, create a wrapper calling + # both it and `manager` + if manager_._set_frame_local_trace: + set_local_trace(manager_, py_frame) + return result diff --git a/line_profiler/c_trace_callbacks.c b/line_profiler/c_trace_callbacks.c new file mode 100644 index 00000000..d036eefd --- /dev/null +++ b/line_profiler/c_trace_callbacks.c @@ -0,0 +1,218 @@ +#include "c_trace_callbacks.h" + +#define CYTHON_MODULE "line_profiler._line_profiler" +#define DISABLE_CALLBACK "disable_line_events" +#define RAISE_IN_CALL(func_name, xc, const_msg) \ + PyErr_SetString(xc, \ + "in `" CYTHON_MODULE "." func_name "()`: " \ + const_msg) + +TraceCallback *alloc_callback() +{ + /* Heap-allocate a new `TraceCallback`. */ + TraceCallback *callback = (TraceCallback*)malloc(sizeof(TraceCallback)); + if (callback == NULL) RAISE_IN_CALL( + // If we're here we have bigger fish to fry... but be nice and + // raise an error explicitly anyway + "alloc_callback", + PyExc_MemoryError, + "failed to allocate memory for storing the existing " + "`sys` trace callback" + ); + return callback; +} + +void free_callback(TraceCallback *callback) +{ + /* Free a heap-allocated `TraceCallback`. */ + if (callback != NULL) free(callback); + return; +} + +void populate_callback(TraceCallback *callback) +{ + /* Store the members `.c_tracefunc` and `.c_traceobj` of the + * current thread on `callback`. + */ + // Shouldn't happen, but just to be safe + if (callback == NULL) return; + // No need to `Py_DECREF()` the thread callback, since it isn't a + // `PyObject` + PyThreadState *thread_state = PyThreadState_Get(); + callback->c_tracefunc = thread_state->c_tracefunc; + callback->c_traceobj = thread_state->c_traceobj; + // No need for NULL check with `Py_XINCREF()` + Py_XINCREF(callback->c_traceobj); + return; +} + +void nullify_callback(TraceCallback *callback) +{ + if (callback == NULL) return; + // No need for NULL check with `Py_XDECREF()` + Py_XDECREF(callback->c_traceobj); + callback->c_tracefunc = NULL; + callback->c_traceobj = NULL; + return; +} + +void restore_callback(TraceCallback *callback) +{ + /* Use `PyEval_SetTrace()` to set the trace callback on the current + * thread to be consistent with the `callback`, then nullify the + * pointers on `callback`. + */ + // Shouldn't happen, but just to be safe + if (callback == NULL) return; + PyEval_SetTrace(callback->c_tracefunc, callback->c_traceobj); + nullify_callback(callback); + return; +} + +inline int is_null_callback(TraceCallback *callback) +{ + return ( + callback == NULL + || callback->c_tracefunc == NULL + || callback->c_traceobj == NULL + ); +} + +int call_callback( + PyObject *disabler, + TraceCallback *callback, + PyFrameObject *py_frame, + int what, + PyObject *arg +) +{ + /* Call the cached trace callback `callback` where appropriate, and + * in a "safe" way so that: + * - If it alters the `sys` trace callback, or + * - If it sets `.f_trace_lines` to false, + * said alterations are reverted so as not to hinder profiling. + * + * Returns: + * - 0 if `callback` is `NULL` or has nullified members; + * - -1 if an error occurs (e.g. when the disabling of line + * events for the frame-local trace function failed); + * - The result of calling said callback otherwise. + * + * Side effects: + * - If the callback unsets the `sys` callback, the `sys` + * callback is preserved but `callback` itself is nullified. + * This is to comply with what Python usually does: if the + * trace callback errors out, `sys.settrace(None)` is called. + * - If a frame-local callback sets the `.f_trace_lines` to + * false, `.f_trace_lines` is reverted but `.f_trace` is + * wrapped/altered so that it no longer sees line events. + * + * Notes: + * It is tempting to assume said current callback value to be + * `{ python_trace_callback, }`, but remember that + * our callback may very well be called via another callback, + * much like how we call the cached callback via + * `python_trace_callback()`. + */ + TraceCallback before, after; + PyObject *mod = NULL, *dle = NULL, *f_trace = NULL; + char f_trace_lines; + int result; + + if (is_null_callback(callback)) return 0; + + f_trace_lines = py_frame->f_trace_lines; + populate_callback(&before); + result = (callback->c_tracefunc)( + callback->c_traceobj, py_frame, what, arg + ); + + // Check if the callback has unset itself; if so, nullify `callback` + populate_callback(&after); + if (is_null_callback(&after)) nullify_callback(callback); + nullify_callback(&after); + restore_callback(&before); + + // Check if a callback has disabled future line events for the + // frame, and if so, revert the change while withholding future line + // events from the callback + if ( + !(py_frame->f_trace_lines) + && f_trace_lines != py_frame->f_trace_lines + ) + { + py_frame->f_trace_lines = f_trace_lines; + if (py_frame->f_trace != NULL && py_frame->f_trace != Py_None) + { + // Note: DON'T `Py_[X]DECREF()` the pointer! Nothing else is + // holding a reference to it. + f_trace = PyObject_CallOneArg(disabler, py_frame->f_trace); + if (f_trace == NULL) + { + // No need to raise another exception, it's already + // raised in the call + result = -1; + goto cleanup; + } + // No need to raise another exception, it's already + // raised in the call + if (PyObject_SetAttrString( + (PyObject *)py_frame, "f_trace", f_trace)) + { + result = -1; + } + } + } +cleanup: + Py_XDECREF(mod); + Py_XDECREF(dle); + return result; +} + +inline void set_local_trace(PyObject *manager, PyFrameObject *py_frame) +{ + /* Set the frame-local trace callable: + * - If there isn't one already, set it to `manager`; + * - Else, call manager.wrap_local_f_trace()` on `py_frame->f_trace` + * where appropriate, setting the frame-local trace callable. + * + * Notes: + * This function is necessary for side-stepping Cython's auto + * memory management, which causes the return value of + * `wrap_local_f_trace()` to trigger the "Casting temporary + * Python object to non-numeric non-Python type" error. + */ + PyObject *method = NULL; + if (manager == NULL || py_frame == NULL) goto cleanup; + // No-op + if (py_frame->f_trace == manager) goto cleanup; + // No local trace function to wrap, just assign `manager` + if (py_frame->f_trace == NULL || py_frame->f_trace == Py_None) + { + Py_INCREF(manager); + py_frame->f_trace = manager; + goto cleanup; + } + // Wrap the trace function + // (No need to raise another exception in case the call or the + // `setattr()` failed, it's already raised in the call) + method = PyUnicode_FromString("wrap_local_f_trace"); + PyObject_SetAttrString( + (PyObject *)py_frame, "f_trace", + PyObject_CallMethodOneArg(manager, method, py_frame->f_trace)); +cleanup: + Py_XDECREF(method); + return; +} + +inline Py_uintptr_t monitoring_restart_version() +#if PY_VERSION_HEX >= 0x030c00b1 // 3.12.0b1 +{ + /* Get the `.last_restart_version` of the interpretor state. + */ + return PyThreadState_GetInterpreter( + PyThreadState_Get())->last_restart_version; +} +#else +{ return (Py_uintptr_t)0; } // Dummy implementation +#endif diff --git a/line_profiler/c_trace_callbacks.h b/line_profiler/c_trace_callbacks.h new file mode 100644 index 00000000..e4238f1b --- /dev/null +++ b/line_profiler/c_trace_callbacks.h @@ -0,0 +1,72 @@ +#ifndef LINE_PROFILER_C_TRACE_CALLBACKS_H +#define LINE_PROFILER_C_TRACE_CALLBACKS_H + +#include "Python_wrapper.h" +#include "frameobject.h" + +/* + * XXX: would make better sense to declare `PyInterpreterState` in + * "Python_wrapper.h", but the file declaring it causes all sorts of + * trouble across various platforms and Python versions... so + * - Only include the file if we are actually using it here, i.e. in + * 3.12+, and + * - Undefine the `_PyGC_FINALIZED()` macro which is removed in 3.13+ + * and causes problems in 3.12 (see CPython #105268, #105350, #107348) + * - Undefine the `HAVE_STD_ATOMIC` macro, which causes problems on + * Linux in 3.12 (see CPython #108216) + * Note in any case that we don't actually use `PyInterpreterState` + * directly -- we just need its memory layout so that we can refer to + * its `.last_restart_version` member + */ + +// _is -> PyInterpreterState +#if PY_VERSION_HEX >= 0x030c00b1 // 3.12.0b6 +# ifndef Py_BUILD_CORE +# define Py_BUILD_CORE 1 +# endif +# ifdef _PyGC_FINALIZED +# undef _PyGC_FINALIZED +# endif +# ifdef HAVE_STD_ATOMIC +# undef HAVE_STD_ATOMIC +# endif +# if PY_VERSION_HEX >= 0x030900a6 // 3.9.0a6 +# include "internal/pycore_interp.h" +# else +# include "internal/pycore_pystate.h" +# endif +#endif + +typedef struct TraceCallback +{ + /* Notes: + * - These fields are synonymous with the corresponding fields + * in a `PyThreadState` object; + * however, note that `PyThreadState.c_tracefunc` is + * considered a CPython implementation detail. + * - It is necessary to reach into the thread-state internals + * like this, because `sys.gettrace()` only retrieves + * `.c_traceobj`, and is thus only valid for Python-level + * trace callables set via `sys.settrace()` (which implicitly + * sets `.c_tracefunc` to + * `Python/sysmodule.c::trace_trampoline()`). + */ + Py_tracefunc c_tracefunc; + PyObject *c_traceobj; +} TraceCallback; + +TraceCallback *alloc_callback(); +void free_callback(TraceCallback *callback); +void populate_callback(TraceCallback *callback); +void restore_callback(TraceCallback *callback); +int call_callback( + PyObject *disabler, + TraceCallback *callback, + PyFrameObject *py_frame, + int what, + PyObject *arg +); +void set_local_trace(PyObject *manager, PyFrameObject *py_frame); +Py_uintptr_t monitoring_restart_version(); + +#endif // LINE_PROFILER_C_TRACE_CALLBACKS_H diff --git a/setup.py b/setup.py index d564fbf7..5a0b0685 100755 --- a/setup.py +++ b/setup.py @@ -229,7 +229,8 @@ def run_cythonize(force=False): Extension( name="line_profiler._line_profiler", sources=["line_profiler/_line_profiler.pyx", - "line_profiler/timers.c"], + "line_profiler/timers.c", + "line_profiler/c_trace_callbacks.c"], language="c++", define_macros=[("CYTHON_TRACE", (1 if os.getenv("DEV") == "true" else 0))], ), diff --git a/tests/test_line_profiler.py b/tests/test_line_profiler.py index 03825e8f..af9237ec 100644 --- a/tests/test_line_profiler.py +++ b/tests/test_line_profiler.py @@ -7,7 +7,7 @@ import textwrap import types import pytest -from line_profiler import LineProfiler +from line_profiler import _line_profiler, LineProfiler def f(x): @@ -680,11 +680,12 @@ def get_func_linenos(func): @pytest.mark.skipif(not hasattr(sys, 'monitoring'), reason='no `sys.monitoring` in version ' f'{".".join(str(v) for v in sys.version_info[:2])}') -def test_sys_monitoring(): +def test_sys_monitoring(monkeypatch): """ Test that `LineProfiler` is properly registered with `sys.monitoring`. """ + monkeypatch.setattr(_line_profiler, 'USE_LEGACY_TRACE', False) profile = LineProfiler() get_name_wrapped = profile(get_profiling_tool_name) tool = get_profiling_tool_name() diff --git a/tests/test_sys_monitoring.py b/tests/test_sys_monitoring.py new file mode 100644 index 00000000..9d518d7f --- /dev/null +++ b/tests/test_sys_monitoring.py @@ -0,0 +1,756 @@ +import inspect +import sys +from collections import Counter +from contextlib import AbstractContextManager, ExitStack +from functools import partial +from io import StringIO +from itertools import count +from types import CodeType, ModuleType +from typing import (Any, Optional, Union, + Callable, Generator, + Dict, FrozenSet, Tuple, + ClassVar) + +import pytest + +from line_profiler import _line_profiler, LineProfiler + + +USE_SYS_MONITORING = isinstance(getattr(sys, 'monitoring', None), ModuleType) + + +# -------------------------------------------------------------------- # +# Helper classes # +# -------------------------------------------------------------------- # + + +class SysMonHelper: + """ + Helper object which helps with simplifying attribute access on + :py:mod:`sys.monitoring`. + """ + tool_id: int + no_tool_id_callables: ClassVar[FrozenSet[str]] = frozenset( + {'restart_events'}) + + def __init__(self, tool_id: Optional[int] = None) -> None: + if tool_id is None: + tool_id = sys.monitoring.PROFILER_ID + self.tool_id = tool_id + + def __getattr__(self, attr: str): + """ + Returns: + * If ``attr`` refers to a :py:mod:`sys.monitoring` callable: + a :py:func:`functools.partial` object with + :py:attr:`~.tool_id` pre-applied, unless it is in the set + of explicitly excluded methods + (:py:attr:`~.no_tool_id_callables`). + * If ``attr`` is all uppercase: + the corresponding integer or special (e.g. + :py:data:`~sys.monitoring.MISSING` and + :py:data:`~sys.monitoring.DISABLE`) constants from either + the module or the :py:data:`sys.monitoring.events` + namespace. + * Otherwise, it falls through to the module. + """ + mon = sys.monitoring + if attr.isupper(): + try: + return getattr(mon.events, attr) + except AttributeError: + pass + result = getattr(mon, attr) + if callable(result) and attr not in self.no_tool_id_callables: + return partial(result, self.tool_id) + return result + + def get_current_callback( + self, event_id: Optional[int] = None) -> Union[Callable, None]: + """ + Arguments: + event_id (int | None) + Optional integer ID to retrieve the callback from; + defaults to :py:data:`sys.monitoring.events.LINE`. + + Returns: + The current callback (if any) associated with with + :py:data:`~.tool_id` and ``event_id``. + """ + register = self.register_callback + if event_id is None: + event_id = MON.LINE + result = register(event_id, None) + if result is not None: + register(event_id, result) + return result + + +class restore_events(AbstractContextManager): + """ + Restore the global or local :py:mod:`sys.monitoring` events. + """ + code: Union[CodeType, None] + mon: SysMonHelper + events: int + + def __init__(self, *, + code: Optional[CodeType] = None, + tool_id: Optional[int] = None) -> None: + self.code = code + self.mon = SysMonHelper(tool_id) + self.events = sys.monitoring.events.NO_EVENTS + + def __enter__(self): + if self.code is None: + self.events = self.mon.get_events() + else: + self.events = self.mon.get_local_events(self.code) + return self + + def __exit__(self, *_, **__) -> None: + if self.mon.get_tool() is None: + pass # No-op + elif self.code is None: + self.mon.set_events(self.events) + else: + self.mon.set_local_events(self.code, self.events) + self.events = self.mon.NO_EVENTS + + +class LineCallback: + """ + Simple :py:mod:`sys.monitoring` callback for handling LINE events. + + Attributes: + nhits (dict[tuple[str, int, str], Counter[int]]) + Mapping from + :py:attr:`line_profiler._line_profiler.LineStats.timings` + keys to a :py:class:`collections.Counter` mapping line + numbers to reported hit counts. + predicate (Callable[[code, int], bool]) + Callable taking the code object and line number, and + returning whether the line event should be reported. + disable (bool) + Settable boolean determining whether to return + :py:data:`sys.monitoring.DISABLE` on a reported line event. + """ + nhits: Dict[Tuple[str, int, str], 'Counter[int]'] + predicate: Callable[[CodeType, int], bool] + disable: bool + + def __init__( + self, + predicate: Callable[[CodeType, int], bool], + *, + register: bool = True, + disable: bool = False + ) -> None: + """ + Arguments: + predicate, disable + See attributes. + register + If true, register the instance with + :py:func:`sys.monitoring.register_callback`. + """ + self.nhits = {} + self.predicate = predicate + self.disable = disable + if register: + self.register() + + def register(self) -> Any: + """ + Returns: + Old value of the :py.mod:`sys.monitoring` callback. + + Side effects: + Instance registered as the new :py:mod:`sys.monitoring` + callback. + """ + return MON.register_callback(MON.LINE, self) + + def handle_line_event(self, code: CodeType, lineno: int) -> bool: + """ + Returns: + Whether a line event has been recorded. + + Side effects: + Entry created/incremented in :py:attr:`~.nhits` if + :py:attr:`~.predicate` evaluates to true. + """ + result = self.predicate(code, lineno) + if result: + self.nhits.setdefault( + _line_profiler.label(code), Counter())[lineno] += 1 + return result + + def __call__(self, code: CodeType, lineno: int) -> Any: + """ + Returns: + :py:data:`sys.monitoring.DISABLE` if :py:attr:`~.predicate` + evaluates to true AND if :py:attr:`~.disable` is true; + :py:const:`None` otherwise. + + Side effects: + Entry created/incremented in :py:attr:`~.nhits` if + :py:attr:`~.predicate` evaluates to true. + """ + if self.handle_line_event(code, lineno) and self.disable: + return MON.DISABLE + + +if USE_SYS_MONITORING: + MON = SysMonHelper() + + +# -------------------------------------------------------------------- # +# Helper functions # +# -------------------------------------------------------------------- # + + +def enable_line_events(code: Optional[CodeType] = None) -> None: + if code is None: + MON.set_events(MON.get_events() | MON.LINE) + else: + MON.set_local_events(code, MON.get_local_events(code) | MON.LINE) + + +def disable_line_events(code: Optional[CodeType] = None) -> None: + if code is None: + events = MON.get_events() + if events & MON.LINE: + MON.set_events(events ^ MON.LINE) + else: + events = MON.get_local_events(code) + if events & MON.LINE: + MON.set_local_events(code, events ^ MON.LINE) + + +# -------------------------------------------------------------------- # +# Tests # +# -------------------------------------------------------------------- # + + +@pytest.fixture(autouse=True) +def sys_mon_cleanup( + monkeypatch: pytest.MonkeyPatch) -> Generator[None, None, None]: + """ + If :py:mod:`sys.monitoring` is available: + * Make sure that we are using the default behavior by overriding + :py:data:`line_profiler._line_profiler.USE_LEGACY_TRACE`; + * Remember all the relevant global callbacks before running the + test; + * If ``sys.monitoring.PROFILER_ID`` isn't already in use, mark it as + being used by `'line_profiler_tests'`; and + * Finally, restore these after the test: + - The callbacks + - The tool name (if we have set it earlier) + - The globally-active events (or the lack thereof) for + ``sys.monitoring.PROFILER_ID`` + + otherwise, automatically :py:func:`pytest.skip` the test. + """ + def restore(message): + for name, callback in callbacks.items(): + prev_callback = MON.register_callback(event_ids[name], callback) + if prev_callback is callback: + callback_repr = '(UNCHANGED)' + else: + callback_repr = '-> ' + repr(callback) + print('{} (`sys.monitoring.events.{}`): {!r} {}'.format( + message, name, prev_callback, callback_repr)) + + if not USE_SYS_MONITORING: + pytest.skip('No `sys.monitoring`') + # Remember the callbacks + event_ids = {name: getattr(MON, name) + for name in ('LINE', 'PY_RETURN', 'PY_YIELD')} + callbacks = {name: MON.register_callback(event_id, None) + for name, event_id in event_ids.items()} + # Restore the callbacks since we "popped" them + restore('Pre-test: putting the callbacks back') + # Set the tool name if it isn't set already + set_tool_id = not MON.get_tool() + if set_tool_id: + MON.use_tool_id('line_profiler_tests') + try: + monkeypatch.setattr(_line_profiler, 'USE_LEGACY_TRACE', False) + with restore_events(): + yield + finally: + # Restore the callbacks + restore('Post-test: restoring the callbacks') + # Unset the temporary tool name + if set_tool_id: + MON.free_tool_id() + + +def test_standalone_callback_usage() -> None: + """ + Check that :py:mod:`sys.monitoring` callbacks behave as expected + when `LineProfiler`s are not in use. + """ + _test_callback_helper(6, 7, 8, 9) + + +@pytest.mark.parametrize('wrap_trace', [True, False]) +def test_wrapping_trace(wrap_trace: bool) -> None: + """ + Check that existing :py:mod:`sys.monitoring` callbacks behave as + expected depending on `LineProfiler.wrap_trace`. + """ + prof = LineProfiler(wrap_trace=wrap_trace) + try: + nhits_expected = _test_callback_helper( + 6, 7, 8, 9, prof=prof, callback_called=wrap_trace) + finally: + with StringIO() as sio: + prof.print_stats(sio) + output = sio.getvalue() + print(output) + line = next(line for line in output.splitlines() + if line.endswith('# Loop body')) + nhits = int(line.split()[1]) + assert nhits == nhits_expected + + +def _test_callback_helper( + nloop_no_trace: int, + nloop_trace_global: int, + nloop_trace_local: int, + nloop_disabled: int, + prof: Optional[LineProfiler] = None, + callback_called: bool = True) -> int: + cumulative_nhits = 0 + + def func(n: int) -> int: + x = 0 + for n in range(1, n + 1): + x += n # Loop body + return x + + def get_loop_hits() -> int: + nonlocal cumulative_nhits + cumulative_nhits = ( + callback.nhits[_line_profiler.label(code)][lineno_loop]) + return cumulative_nhits + + lines, first_lineno = inspect.getsourcelines(func) + lineno_loop = first_lineno + next( + offset for offset, line in enumerate(lines) + if line.rstrip().endswith('# Loop body')) + names = {func.__name__, func.__qualname__} + code = func.__code__ + if prof is not None: + orig_func, func = func, prof(func) + code = orig_func.__code__ + callback = LineCallback(lambda code, _: code.co_name in names) + + # When line events are suppressed, nothing should happen + with restore_events(): + disable_line_events() + n = nloop_no_trace + assert MON.get_current_callback() is callback + assert func(n) == n * (n + 1) // 2 + assert MON.get_current_callback() is callback + assert not callback.nhits + + # When line events are activated, the callback should see line + # events + with restore_events(): # Global events + enable_line_events() + n = nloop_trace_global + assert MON.get_current_callback() is callback + assert func(n) == n * (n + 1) // 2 + assert MON.get_current_callback() is callback + print(callback.nhits) + if callback_called: + expected = cumulative_nhits + n + assert get_loop_hits() == expected + else: + assert not callback.nhits + with ExitStack() as stack: + stack.enter_context(restore_events()) + stack.enter_context(restore_events(code=code)) + # Disable global line events, and enable local line events + disable_line_events() + enable_line_events(code) + n = nloop_trace_local + assert MON.get_current_callback() is callback + assert func(n) == n * (n + 1) // 2 + assert MON.get_current_callback() is callback + print(callback.nhits) + if callback_called: + expected = cumulative_nhits + n + assert get_loop_hits() == expected + else: + assert not callback.nhits + + # Line events can be disabled on the specific line by returning + # `sys.monitoring.DISABLE` from the callback + for enable_global in True, False: + callback.disable = True + with ExitStack() as stack: + stack.enter_context(restore_events()) + stack.enter_context(restore_events(code=code)) + # Set the global and local events + # (doesn't matter if events are enabled globally or not) + if enable_global: + enable_line_events() + else: + disable_line_events() + enable_line_events(code) + # We still get 1 more hit because that's the call we + # return `sys.monitoring.DISABLE` from + n = nloop_disabled + assert MON.get_current_callback() is callback + assert func(n) == n * (n + 1) // 2 + assert MON.get_current_callback() is callback + print(callback.nhits) + if callback_called: + expected = cumulative_nhits + 1 + assert get_loop_hits() == expected + else: + assert not callback.nhits + MON.restart_events() + + # Return the total number of loops run + # (Note: `nloop_disabled` is used twice) + return (nloop_no_trace + + nloop_trace_global + + nloop_trace_local + + 2 * nloop_disabled) + + +@pytest.mark.parametrize('standalone', [True, False]) +def test_callback_switching(standalone: bool) -> None: + """ + Check that hot-swapping of :py:mod:`sys.monitoring` callbacks + behaves as expected, no matter if `LineProfiler`s are in use. + """ + if standalone: + prof: Union[LineProfiler, None] = None + else: + prof = LineProfiler(wrap_trace=True) + + try: + nhits_expected = _test_callback_switching_helper(17, prof) + finally: + if prof is not None: + with StringIO() as sio: + prof.print_stats(sio) + output = sio.getvalue() + print(output) + if prof is None: + return + + line = next(line for line in output.splitlines() + if line.endswith('# Loop body')) + nhits = int(line.split()[1]) + assert nhits == nhits_expected + + +def _test_callback_switching_helper( + nloop: int, prof: Optional[LineProfiler] = None) -> int: + cumulative_nhits = 0, 0 + + def func(n: int) -> int: + x = 0 + for n in range(1, n + 1): + x += n # Loop body + return x + + def get_loop_hits() -> Tuple[int, int]: + nonlocal cumulative_nhits + cumulative_nhits = tuple( # type: ignore[assignment] + callback.nhits.get( + _line_profiler.label(code), Counter())[lineno_loop] + for callback in (callback_1, callback_2)) + return cumulative_nhits + + def predicate(code: CodeType, lineno: int) -> bool: + return code.co_name in names and lineno == lineno_loop + + class SwitchingCallback(LineCallback): + """ + Callback which switches to the next one after having been + triggered. + """ + next: Union['SwitchingCallback', None] + + def __init__(self, *args, + next: Optional['SwitchingCallback'] = None, + **kwargs) -> None: + super().__init__(*args, **kwargs) + self.next = next + + def __call__(self, code: CodeType, lineno: int) -> Any: + if not self.handle_line_event(code, lineno): + return + if self.next is not None: + self.next.register() + if self.disable: + return MON.DISABLE + + lines, first_lineno = inspect.getsourcelines(func) + lineno_loop = first_lineno + next( + offset for offset, line in enumerate(lines) + if line.rstrip().endswith('# Loop body')) + names = {func.__name__, func.__qualname__} + code = func.__code__ + if prof is not None: + orig_func, func = func, prof(func) + code = orig_func.__code__ + + # The two callbacks hand off to one another in a loop + callback_1 = SwitchingCallback(predicate) + callback_2 = SwitchingCallback(predicate, register=False, next=callback_1) + callback_1.next = callback_2 + + with restore_events(): + enable_line_events() + assert MON.get_current_callback() is callback_1 + assert func(nloop) == nloop * (nloop + 1) // 2 + assert MON.get_current_callback() in (callback_1, callback_2) + print(callback_1.nhits, callback_2.nhits) + nhits_one = nloop // 2 + nhits_other = nloop - nhits_one + if nhits_one == nhits_other: + assert get_loop_hits() == (nhits_one, nhits_other) + else: # Odd number + assert get_loop_hits() in ((nhits_one, nhits_other), + (nhits_other, nhits_one)) + + return nloop + + +@pytest.mark.parametrize('add_events', [True, False]) +@pytest.mark.parametrize('code_local_events', [True, False]) +@pytest.mark.parametrize('start_with_events', [True, False]) +@pytest.mark.parametrize('standalone', [True, False]) +def test_callback_update_events( + standalone: bool, start_with_events: bool, + code_local_events: bool, add_events: bool) -> None: + """ + Check that a :py:mod:`sys.monitoring` callback which updates the + event set (global and code-object-local) after a certain number of + hits behaves as expected, no matter if `LineProfiler`s are in use. + """ + nloop = 10 + nloop_update = 5 + cumulative_nhits = 0 + + def func(n: int) -> int: + x = 0 + for n in range(1, n + 1): + x += n # Loop body + return x + + def get_loop_hits() -> int: + nonlocal cumulative_nhits + cumulative_nhits = ( + callback.nhits[_line_profiler.label(code)][lineno_loop]) + return cumulative_nhits + + class EventUpdatingCallback(LineCallback): + """ + Callback which, after a certain number of hits: + - Disables :py:attr:`sys.monitoring.LINE` events, and + - Enables :py:attr:`sys.monitoring.CALL` events (if + :py:attr:`~.call` is true) + """ + def __init__(self, *args, + code: Optional[CodeType] = None, call: bool = False, + **kwargs) -> None: + super().__init__(*args, **kwargs) + self.count = 0 + self.code = code + self.call = call + + def __call__(self, code: CodeType, lineno: int) -> None: + if not self.handle_line_event(code, lineno): + return + self.count += 1 + if self.count >= nloop_update: + disable_line_events(self.code) + if not self.call: + return + if self.code is None: + MON.set_events(MON.get_events() | MON.CALL) + else: + MON.set_local_events( + self.code, MON.get_local_events(self.code) | MON.CALL) + + lines, first_lineno = inspect.getsourcelines(func) + lineno_loop = first_lineno + next( + offset for offset, line in enumerate(lines) + if line.rstrip().endswith('# Loop body')) + names = {func.__name__, func.__qualname__} + code = func.__code__ + + if standalone: + prof: Union[LineProfiler, None] = None + else: + prof = LineProfiler(wrap_trace=True) + if start_with_events: + global_events = MON.CALL + else: + global_events = MON.NO_EVENTS + if prof is not None: + orig_func, func = func, prof(func) + code = orig_func.__code__ + + callback = EventUpdatingCallback( + lambda code, lineno: (code.co_name in names and lineno == lineno_loop), + code=code if code_local_events else None, + call=add_events) + + local_events = local_events_after = MON.NO_EVENTS + global_events_after = global_events + if code_local_events: + local_events |= MON.LINE + if add_events: + local_events_after |= MON.CALL + else: + global_events |= MON.LINE + if add_events: + global_events_after |= MON.CALL + MON.set_events(global_events) + MON.set_local_events(code, local_events) + + try: + # Check that data is only gathered for the first `nloop_update` + # hits + assert MON.get_current_callback() is callback + assert func(nloop) == nloop * (nloop + 1) // 2 + assert MON.get_current_callback() is callback + print(callback.nhits) + assert get_loop_hits() == nloop_update + # Check that the callback has disabled LINE events (and enabled + # CALL events where appropriate) + assert MON.get_events() == global_events_after + assert MON.get_local_events(code) == local_events_after + finally: + if prof is not None: + with StringIO() as sio: + prof.print_stats(sio) + output = sio.getvalue() + print(output) + if prof is None: + return + + line = next(line for line in output.splitlines() + if line.endswith('# Loop body')) + nhits = int(line.split()[1]) + assert nhits == nloop + + +@pytest.mark.parametrize('standalone', [True, False]) +def test_callback_toggle_local_events(standalone: bool) -> None: + """ + Check that a :py:mod:`sys.monitoring` callback which disables local + LINE events and later re-enables them with + :py:func:`sys.monitoring.restart_events` behaves as expected, no + matter if `LineProfiler`s are in use. + """ + if standalone: + prof: Union[LineProfiler, None] = None + else: + prof = LineProfiler(wrap_trace=True) + + try: + nhits_expected = _test_callback_toggle_local_events_helper( + 17, 18, 19, prof) + finally: + if prof is not None: + with StringIO() as sio: + prof.print_stats(sio) + output = sio.getvalue() + print(output) + if prof is None: + return + + line = next(line for line in output.splitlines() + if line.endswith('# Loop body')) + nhits = int(line.split()[1]) + assert nhits == nhits_expected + + +def _test_callback_toggle_local_events_helper( + nloop_before_disabling: int, + nloop_when_disabled: int, + nloop_after_reenabling: int, + prof: Optional[LineProfiler] = None) -> int: + cumulative_nhits = 0 + + def func(*nloops) -> int: + x = 0 + counter = count(1) + for n in nloops: + for _ in range(n): + x += next(counter) # Loop body + pass # Switching location + return x + + def get_loop_hits() -> int: + nonlocal cumulative_nhits + cumulative_nhits = ( + callback.nhits[_line_profiler.label(code)][lineno_loop]) + return cumulative_nhits + + class LocalDisablingCallback(LineCallback): + """ + Callback which disables LINE events locally after a certain + number of hits + """ + def __init__(self, *args, **kwargs) -> None: + super().__init__(*args, **kwargs) + self.switch_count = 0 + + def __call__(self, code: CodeType, lineno: int) -> Any: + if not self.handle_line_event(code, lineno): + return + # When we hit the "loop" line after having hit the "switch" + # line, disable line events on the "loop" line + if lineno == lineno_loop and self.switch_count % 2: + # Remove the recorded hit + self.nhits[_line_profiler.label(code)][lineno] -= 1 + return MON.DISABLE + # When we hit the "switch" line the second line, restart + # events to undo disabling of the "loop" line + if lineno == lineno_switch: + if self.switch_count % 2: + MON.restart_events() + self.switch_count += 1 + return + + lines, first_lineno = inspect.getsourcelines(func) + lineno_loop = first_lineno + next( + offset for offset, line in enumerate(lines) + if line.rstrip().endswith('# Loop body')) + lineno_switch = first_lineno + next( + offset for offset, line in enumerate(lines) + if line.rstrip().endswith('# Switching location')) + linenos = {lineno_loop, lineno_switch} + names = {func.__name__, func.__qualname__} + code = func.__code__ + if prof is not None: + orig_func, func = func, prof(func) + code = orig_func.__code__ + + callback = LocalDisablingCallback( + lambda code, lineno: (code.co_name in names and lineno in linenos)) + + MON.set_events(MON.get_events() | MON.LINE) + n = nloop_before_disabling + nloop_when_disabled + nloop_after_reenabling + assert MON.get_current_callback() is callback + assert func(nloop_before_disabling, + nloop_when_disabled, + nloop_after_reenabling) == n * (n + 1) // 2 + assert MON.get_current_callback() is callback + print(callback.nhits) + assert get_loop_hits() == nloop_before_disabling + nloop_after_reenabling + + return n diff --git a/tests/test_sys_trace.py b/tests/test_sys_trace.py new file mode 100644 index 00000000..6210fbd0 --- /dev/null +++ b/tests/test_sys_trace.py @@ -0,0 +1,648 @@ +""" +Test the interoperability between `LineProfiler` and other `sys` tracing +facilities (e.g. Python functions registered via `sys.settrace()`. + +Notes +----- +- By the very nature of the tests in this test module, they override + `sys` trace functions, and are thus largely opaque towards + `coverage.py`. +- However, there effects are isolated since each test is run in a + separate Python subprocess. +""" +import concurrent.futures +import functools +import inspect +import linecache +import os +import subprocess +import shlex +import sys +import time +import tempfile +import textwrap +import threading +import pytest +from ast import literal_eval +from contextlib import nullcontext +from io import StringIO +from types import FrameType, ModuleType +from typing import Any, Optional, Union, Callable, List, Literal +from line_profiler import LineProfiler + + +# Common utilities + +DEBUG = False +USE_SYS_MONITORING = isinstance(getattr(sys, 'monitoring', None), ModuleType) + +Event = Literal['call', 'line', 'return', 'exception', 'opcode'] +TracingFunc = Callable[[FrameType, Event, Any], Union['TracingFunc', None]] + + +def strip(s: str) -> str: + return textwrap.dedent(s).strip('\n') + + +def isolate_test_in_subproc( + func: Optional[Callable] = None, debug: bool = DEBUG) -> Callable: + """ + Run the test function with the supplied arguments in a subprocess so + that it doesn't pollute the state of the current interpretor. + If `debug` is true, run with `pytest` for more detailed traceback. + + Notes + ----- + - Code is written to a tempfile and run in a subprocess. + - The test function should be import-able from the top-level + namespace of this file. + - All the arguments should be `ast.literal_eval()`-able. + - Beware of using fixtures for these tests. + """ + if func is None: + return functools.partial(isolate_test_in_subproc, debug=debug) + + def message(msg: str, header: str, *, + short: bool = False, **kwargs) -> None: + header = strip(header) + if not header.endswith(':'): + header += ':' + kwargs['sep'] = '\n' + if short and len(msg.splitlines()) < 2: + print('', f'{header} {msg}', **kwargs) + return + print('', header, textwrap.indent(msg, ' '), **kwargs) + + @functools.wraps(func) + def wrapper(*args, **kwargs): + # Check if the function is importable + test_func = func.__name__ + assert globals()[test_func].__subproc_test_inner__ is func + + # Check if the arguments are round-trippable + assert literal_eval(repr(args)) == args + assert literal_eval(repr(kwargs)) == kwargs + + # Write a test script + args_reprs = ([repr(a) for a in args] + + [f'{k}={v!r}' for k, v in kwargs.items()]) + if len(args_reprs) > 1: + args_repr = '\n' + textwrap.indent(',\n'.join(args_reprs), ' ' * 8) + else: + args_repr = ', '.join(args_reprs) + code_template = strip(""" + import sys + sys.path.insert(0, # Let the test import from this file + {path!r}) + from {mod} import ( # Import the test func from this file + {test} as _{test}) + + def {test}(): + _{test}.__subproc_test_inner__({args}) + + if __name__ == '__main__': + {test}() + """) + test_dir, test_filename = os.path.split(__file__) + test_module_name, dot_py = os.path.splitext(test_filename) + assert dot_py == '.py' + code = code_template.format(path=test_dir, mod=test_module_name, + test=test_func, args=args_repr) + # Run the test script in a subprocess + if debug: # Use `pytest` to get perks like assertion rewriting + cmd = [sys.executable, '-m', 'pytest', '-s'] + else: + cmd = [sys.executable] + with tempfile.TemporaryDirectory() as tmpdir: + curdir = os.path.abspath(os.curdir) + os.chdir(tmpdir) + fname = 'my_test.py' + cmd.append(fname) + message(code, f'Test code run ({shlex.quote(fname)})') + message(shlex.join(cmd), 'Executed command') + try: + with open(fname, mode='w') as fobj: + print(code, file=fobj) + env = os.environ.copy() + # Make sure that we're testing the "default behavior" + env.pop('LINE_PROFILER_CORE', '') + proc = subprocess.run( + cmd, capture_output=True, env=env, text=True) + finally: + os.chdir(curdir) + if proc.stdout: + message(proc.stdout, 'Stdout') + else: + message('', 'Stdout', short=True) + if proc.stderr: + message(proc.stderr, 'Stderr', file=sys.stderr) + else: + message('', 'Stderr', short=True) + proc.check_returncode() + + wrapper.__subproc_test_inner__ = func + return wrapper + + +def foo(n: int) -> int: + result = 0 + for spam in range(1, n + 1): + result += spam + return result + + +def bar(n: int) -> int: + result = 0 + for ham in range(1, n + 1): + result += ham + return result + + +def baz(n: int) -> int: + result = 0 + for eggs in range(1, n + 1): + result += eggs + return result + + +class suspend_tracing: + def __init__(self): + self.callback = None + self.events = 0 + + def __enter__(self): + if USE_SYS_MONITORING: + mod = sys.monitoring + self.events = mod.get_events(mod.PROFILER_ID) + mod.set_events(mod.PROFILER_ID, mod.events.NO_EVENTS) + else: + self.callback = sys.gettrace() + sys.settrace(None) + + def __exit__(self, *_, **__): + if USE_SYS_MONITORING: + mod = sys.monitoring + mod.set_events(mod.PROFILER_ID, self.events) + self.events = 0 + else: + sys.settrace(self.callback) + self.callback = None + + +def get_incr_logger(logs: List[str], func: Literal[foo, bar, baz] = foo, *, + bugged: bool = False, + report_return: bool = False) -> TracingFunc: + ''' + Append a ': spam = <...>' message whenever we hit the line in + `func()` containing the incrementation of `result`. + If it's made `bugged`, it sets the frame's `.f_trace_lines` to false + after writing the first log entry, disabling line events. + If `report_return` is true, a 'Returning from ()' log entry + is written on return. + ''' + def callback( + frame: FrameType, event: Event, _) -> Union[TracingFunc, None]: + if DEBUG and callback.emit_debug: + print('{0.co_filename}:{1.f_lineno} - {0.co_name} ({2})' + .format(frame.f_code, frame, event)) + if event == 'call': # Set up tracing for nested scopes + return callback + if event not in events: # Only trace the specified events + return + code = frame.f_code + if code.co_filename != filename or code.co_name != func_name: + return + if event == 'return': # Write a return entry where appropriate + logs.append(f'Returning from `{func_name}()`') + return + if frame.f_lineno == lineno: + # Add log entry whenever the target line is hit + counter_value = frame.f_locals.get(counter) + logs.append(f'{func_name}: {counter} = {counter_value}') + if bugged: # Line-event tracing turned off after first hit + frame.f_trace_lines = False + return callback + + # Get data from `func()`: its (file-)name, the line number of the + # incrementation, and the name of the counter variable + func_name = func.__name__ + filename = func.__code__.co_filename + lineno = func.__code__.co_firstlineno + block = inspect.getblock(linecache.getlines(__file__)[lineno - 1:]) + (offset, line), = ((i, line) for i, line in enumerate(block) + if 'result +=' in line) + lineno += offset + counter = line.split()[-1] + + events = {'line'} + if report_return: + events.add('return') + + callback.emit_debug = False + return callback + + +def get_return_logger(logs: List[str], *, bugged: bool = False) -> TracingFunc: + ''' + Append a 'Returning from `()`' message whenever we hit return + from a function defined in this file. If it's made `bugged`, it + panics and errors out when returning from `bar`, thus unsetting the + `sys` trace. + ''' + def callback( + frame: FrameType, event: Event, _) -> Union[TracingFunc, None]: + if DEBUG and callback.emit_debug: + print('{0.co_filename}:{1.f_lineno} - {0.co_name} ({2})' + .format(frame.f_code, frame, event)) + if event == 'call': + # Set up tracing for nested scopes + return callback + if event != 'return': + return # Only trace return events + code = frame.f_code + if code.co_filename != __file__: + return # Only trace functions in this file + # Add log entry + logs.append(f'Returning from `{code.co_name}()`') + if bugged and code.co_name == 'bar': + # Error out and cause `sys.settrace(None)` + raise MyException + + callback.emit_debug = False + return callback + + +class MyException(Exception): + """Unique exception raised by some of the tests.""" + pass + + +# Tests + + +def _test_helper_callback_preservation( + callback: Union[TracingFunc, None]) -> None: + sys.settrace(callback) + assert sys.gettrace() is callback, f'can\'t set trace to {callback!r}' + profile = LineProfiler(wrap_trace=False) + profile.enable_by_count() + if not USE_SYS_MONITORING: + assert profile in sys.gettrace().active_instances, ( + 'can\'t set trace to the profiler') + profile.disable_by_count() + assert sys.gettrace() is callback, f'trace not restored to {callback!r}' + sys.settrace(None) + + +@isolate_test_in_subproc +def test_callback_preservation(): + """ + Test in a subprocess that the profiler restores the active `sys` + trace callback (or the lack thereof) after it's `.disable()`-ed. + """ + _test_helper_callback_preservation(None) + _test_helper_callback_preservation(lambda frame, event, arg: None) + + +@pytest.mark.parametrize('set_frame_local_trace', [True, False]) +@pytest.mark.parametrize( + ('label', 'use_profiler', 'wrap_trace'), + [('base case', False, False), + ('profiled (trace suspended)', True, False), + ('profiled (trace wrapped)', True, True)]) +@isolate_test_in_subproc +def test_callback_wrapping( + label: str, use_profiler: bool, + wrap_trace: bool, set_frame_local_trace: bool) -> None: + """ + Test in a subprocess that the profiler can wrap around an existing + trace callback such that we both profile the code and do whatever + the existing callback does. + """ + logs = [] + my_callback = get_incr_logger(logs) + sys.settrace(my_callback) + + if use_profiler: + profile = LineProfiler( + wrap_trace=wrap_trace, set_frame_local_trace=set_frame_local_trace) + foo_like = profile(foo) + trace_preserved = wrap_trace + else: + foo_like = foo + trace_preserved = True + if trace_preserved or USE_SYS_MONITORING: + exp_logs = [f'foo: spam = {spam}' for spam in range(1, 6)] + else: + exp_logs = [] + + assert sys.gettrace() is my_callback, 'can\'t set custom trace' + my_callback.emit_debug = True + x = foo_like(5) + my_callback.emit_debug = False + assert x == 15, f'expected `foo(5) = 15`, got {x!r}' + assert sys.gettrace() is my_callback, 'trace not restored afterwards' + + # Check that the existing trace function has been called where + # appropriate + print(f'Logs: {logs!r}') + assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}' + + # Check that the profiling is as expected: 5 hits on the + # incrementation line + if not use_profiler: + return + with StringIO() as sio: + profile.print_stats(stream=sio, summarize=True) + out = sio.getvalue() + print(out) + line, = (line for line in out.splitlines() if '+=' in line) + nhits = int(line.split()[1]) + assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}' + + +@pytest.mark.parametrize( + ('label', 'use_profiler', 'enable_count'), + [('base case', False, 0), + ('profiled (isolated)', True, 0), + ('profiled (continuous)', True, 1)]) +@isolate_test_in_subproc +def test_wrapping_throwing_callback( + label: str, use_profiler: bool, enable_count: int) -> None: + """ + Test in a subprocess that if the profiler wraps around an existing + trace callback that errors out: + - Profiling continues uninterrupted. + - The errored-out trace callback is no longer called from the + profiling traceback. + - The `sys` traceback is set to `None` when the profiler is + `.disable()`-ed. + + Notes + ----- + Extra `enable_count` means that the profiler stays enabled between + the calls to the profiled functions, and we thereyby test against + these problematic behaviors after `my_callback()` bugs out: + - If the profiler stops profiling (because the `sys` trace callback + is unset), or + - If the profiler's callback keeps calling `my_callback()` + afterwards. + """ + logs = [] + my_callback = get_return_logger(logs, bugged=True) + sys.settrace(my_callback) + assert sys.gettrace() is my_callback, 'can\'t set custom trace' + + if use_profiler: + profile = LineProfiler(wrap_trace=True) + foo_like, bar_like, baz_like = profile(foo), profile(bar), profile(baz) + else: + foo_like, bar_like, baz_like = foo, bar, baz + enable_count = 0 + + for _ in range(enable_count): + profile.enable_by_count() + my_callback.emit_debug = True + x = foo_like(3) # This is logged + try: + _ = bar_like(4) # This is also logged, but... + except MyException: + # ... the trace func errors out as `bar()` returns, and as such + # disables itself + pass + else: + assert False, 'tracing function didn\'t error out' + y = baz_like(5) # Not logged because trace disabled itself + my_callback.emit_debug = False + for _ in range(enable_count): + profile.disable_by_count() + + assert x == 6, f'expected `foo(3) = 6`, got {x!r}' + assert y == 15, f'expected `baz(5) = 15`, got {y!r}' + assert sys.gettrace() is None, ( + '`sys` trace = {sys.gettrace()!r} not reset afterwards') + + # Check that the existing trace function has been called where + # appropriate + print(f'Logs: {logs!r}') + exp_logs = ['Returning from `foo()`', 'Returning from `bar()`'] + assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}' + + # Check that the profiling is as expected: 3 (resp. 4, 5) hits on + # the incrementation line for `foo()` (resp. `bar()`, `baz()`) + if not use_profiler: + return + with StringIO() as sio: + profile.print_stats(stream=sio, summarize=True) + out = sio.getvalue() + print(out) + for func, marker, exp_nhits in [('foo', 'spam', 3), ('bar', 'ham', 4), + ('baz', 'eggs', 5)]: + line, = (line for line in out.splitlines() + if line.endswith('+= ' + marker)) + nhits = int(line.split()[1]) + assert nhits == exp_nhits, (f'expected {exp_nhits} ' + f'profiler hits, got {nhits!r}') + + +@pytest.mark.parametrize(('label', 'use_profiler'), + [('base case', False), ('profiled', True)]) +@isolate_test_in_subproc +def test_wrapping_line_event_disabling_callback(label: str, + use_profiler: bool) -> None: + """ + Test in a subprocess that if the profiler wraps around an existing + trace callback that disables `.f_trace_lines`: + - Profiling continues uninterrupted. + - `.f_trace` is subsequently disabled, but only for line events in + that frame. + """ + logs = [] + my_callback = get_incr_logger(logs, bugged=True, report_return=True) + sys.settrace(my_callback) + + if use_profiler: + profile = LineProfiler(wrap_trace=True) + foo_like = profile(foo) + else: + foo_like = foo + + assert sys.gettrace() is my_callback, 'can\'t set custom trace' + my_callback.emit_debug = True + x = foo_like(5) + my_callback.emit_debug = False + assert x == 15, f'expected `foo(5) = 15`, got {x!r}' + assert sys.gettrace() is my_callback, 'trace not restored afterwards' + + # Check that the trace function has been called exactly once on the + # line event, and once on the return event + print(f'Logs: {logs!r}') + exp_logs = ['foo: spam = 1', 'Returning from `foo()`'] + assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}' + + # Check that the profiling is as expected: 5 hits on the + # incrementation line + if not use_profiler: + return + with StringIO() as sio: + profile.print_stats(stream=sio, summarize=True) + out = sio.getvalue() + print(out) + line, = (line for line in out.splitlines() if '+=' in line) + nhits = int(line.split()[1]) + assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}' + + +def _test_helper_wrapping_thread_local_callbacks( + profile: Union[LineProfiler, None], sleep: float = .0625) -> str: + logs = [] + if threading.current_thread() == threading.main_thread(): + thread_label = 'main' + func = foo + my_callback = get_incr_logger(logs, func) + exp_logs = [f'foo: spam = {spam}' for spam in range(1, 6)] + else: + thread_label = 'side' + func = bar + my_callback = get_return_logger(logs) + exp_logs = ['Returning from `bar()`'] + if profile is None: + func_like = func + else: + func_like = profile(func) + print(f'Thread: {threading.get_ident()} ({thread_label})') + + # Check result + sys.settrace(my_callback) + assert sys.gettrace() is my_callback, 'can\'t set custom trace' + my_callback.emit_debug = True + x = func_like(5) + my_callback.emit_debug = False + assert x == 15, f'expected `{func.__name__}(5) = 15`, got {x!r}' + assert sys.gettrace() is my_callback, 'trace not restored afterwards' + + # Check logs + print(f'Logs ({thread_label} thread): {logs!r}') + assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}' + time.sleep(sleep) + return '\n'.join(logs) + + +@pytest.mark.parametrize(('label', 'use_profiler'), + [('base case', False), ('profiled', True)]) +@isolate_test_in_subproc +def test_wrapping_thread_local_callbacks(label: str, + use_profiler: bool) -> None: + """ + Test in a subprocess that the profiler properly handles thread-local + `sys` trace callbacks. + """ + profile = LineProfiler(wrap_trace=True) if use_profiler else None + expected_results = { + # From the main thread + '\n'.join(f'foo: spam = {spam}' for spam in range(1, 6)), + # From the other thread + 'Returning from `bar()`', + } + + # Run tasks (and so some basic checks) + results = set() + with concurrent.futures.ThreadPoolExecutor(max_workers=1) as executor: + tasks = [] + tasks.append(executor.submit( # This is run on a side thread + _test_helper_wrapping_thread_local_callbacks, profile)) + # This is run on the main thread + results.add(_test_helper_wrapping_thread_local_callbacks(profile)) + results.update( + future.result() + for future in concurrent.futures.as_completed(tasks)) + assert results == expected_results, (f'expected {expected_results!r}, ' + f'got {results!r}') + + # Check profiling + if profile is None: + return + with StringIO() as sio: + profile.print_stats(stream=sio, summarize=True) + out = sio.getvalue() + print(out) + for var in 'spam', 'ham': + line, = (line for line in out.splitlines() + if line.endswith('+= ' + var)) + nhits = int(line.split()[1]) + assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}' + + +@pytest.mark.parametrize( + ('stay_in_scope', 'set_frame_local_trace', 'n', 'nhits'), + [(True, True, 100, {0: 2, # Both calls are traced + 5: 0, # Tracing suspended + 7: 100}), # Tracing restored (both calls) + # If `set_frame_local_trace` is false: + # - When using legacy tracing, tracing is suspended for the rest of + # the frame + # - Else, tracing is unaffected + (True, False, 100, + {0: 2, 5: 0, 7: 100 if USE_SYS_MONITORING else 0}), + # Calling a function always triggers `.__call__()` + (False, True, 100, {0: 1, # Only one of the calls is traced + 2: 100}), # 100 hits on the line in the loop + (False, False, 100, {0: 1, 2: 100})]) +@isolate_test_in_subproc +def test_python_level_trace_manipulation( + stay_in_scope, set_frame_local_trace, n, nhits): + """ + Test that: + - When Python code retrieves the trace object set by `line_profiler` + with `sys.gettrace()` and later restores it via `sys.settrace()`, + it doesn't break anything, and + - Resumption of line profiling in the same frame thereafter happens + if and only if `set_frame_local_trace` is true. + """ + prof = LineProfiler(set_frame_local_trace=set_frame_local_trace) + + def func_no_break(n): + x = 0 + for n in range(1, n + 1): + x += n + return x + + @prof + def func_break_in_middle(n): + x = 0 + n_not_traced = n // 2 + n_traced = n - n_not_traced + with suspend_tracing(): + for n in range(1, n_not_traced + 1): + x += n + for n in range(n_not_traced + 1, n_not_traced + n_traced + 1): + x += n + return x + + prof.add_callable(func_no_break) + expected = n * (n + 1) // 2 + + if stay_in_scope: + # Do two calls, each with tracing suspended for half of the loop + outer_ctx = inner_ctx = nullcontext() + func = func_break_in_middle + else: + # Do one call with tracing suspended, then another with it + # restored + outer_ctx = prof + inner_ctx = suspend_tracing() + func = func_no_break + with outer_ctx: + with inner_ctx: + assert func(n) == expected + assert func(n) == expected + timings = prof.get_stats().timings + print(timings) + prof.print_stats() + entries = next(entries for (*_, func_name), entries in timings.items() + if func_name.endswith(func.__name__)) + body_start_line = min(lineno for (lineno, *_) in entries) + all_nhits = {lineno - body_start_line: _nhits + for (lineno, _nhits, _) in entries} + all_nhits = {lineno: all_nhits.get(lineno, 0) for lineno in nhits} + assert all_nhits == nhits, f'expected {nhits=}, got {all_nhits=}'