diff --git a/CHANGELOG.rst b/CHANGELOG.rst index c6e5085d..2abb86ed 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -24,6 +24,7 @@ Changes * On-import profiling is now more aggressive so that it doesn't miss entities 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`` 4.2.0 ~~~~~ diff --git a/docs/source/auto/line_profiler.unset_trace.rst b/docs/source/auto/line_profiler.unset_trace.rst deleted file mode 100644 index d2e4bcc8..00000000 --- a/docs/source/auto/line_profiler.unset_trace.rst +++ /dev/null @@ -1,7 +0,0 @@ -line\_profiler.unset\_trace module -================================== - -.. automodule:: line_profiler.unset_trace - :members: - :undoc-members: - :show-inheritance: diff --git a/line_profiler/CMakeLists.txt b/line_profiler/CMakeLists.txt index a4192ad4..6f0e0844 100644 --- a/line_profiler/CMakeLists.txt +++ b/line_profiler/CMakeLists.txt @@ -9,7 +9,6 @@ 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}/unset_trace.c" "${CMAKE_CURRENT_SOURCE_DIR}/timers.c" ) message(STATUS "[OURS] sources = ${sources}") diff --git a/line_profiler/_line_profiler.pyx b/line_profiler/_line_profiler.pyx index 622dbf84..15510317 100644 --- a/line_profiler/_line_profiler.pyx +++ b/line_profiler/_line_profiler.pyx @@ -11,8 +11,7 @@ Ignore: # Assuming the cwd is the repo root. cythonize --annotate --inplace \ ./line_profiler/_line_profiler.pyx \ - ./line_profiler/timers.c \ - ./line_profiler/unset_trace.c + ./line_profiler/timers.c """ from .python25 cimport PyFrameObject, PyObject, PyStringObject from sys import byteorder @@ -22,8 +21,10 @@ from cpython.version cimport PY_VERSION_HEX from libc.stdint cimport int64_t from libcpp.unordered_map cimport unordered_map +import functools import threading import opcode +import os import types NOP_VALUE: int = opcode.opmap['NOP'] @@ -36,6 +37,16 @@ NOP_BYTES: bytes = NOP_VALUE.to_bytes(2, 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) +CANNOT_LINE_TRACE_CYTHON = ( + CAN_USE_SYS_MONITORING and PY_VERSION_HEX < 0x030d00b1) + # long long int is at least 64 bytes assuming c99 ctypedef unsigned long long int uint64 ctypedef long long int int64 @@ -43,19 +54,29 @@ 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": """ - inline PyObject* get_frame_code(PyFrameObject* frame) { - #if PY_VERSION_HEX < 0x030B0000 - Py_INCREF(frame->f_code->co_code); - return frame->f_code->co_code; - #else - PyCodeObject* code = PyFrame_GetCode(frame); - PyObject* ret = PyCode_GetCode(code); - Py_DECREF(code); - return ret; - #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. + */ + 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 object get_frame_code(PyFrameObject* frame) + 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": @@ -71,7 +92,6 @@ cdef extern from "Python.h": #endif """ ctypedef struct PyFrameObject - ctypedef struct PyCodeObject ctypedef long long PY_LONG_LONG cdef bint PyCFunction_Check(object obj) cdef int PyCode_Addr2Line(PyCodeObject *co, int byte_offset) @@ -107,9 +127,6 @@ cdef extern from "timers.c": PY_LONG_LONG hpTimer() double hpTimerUnit() -cdef extern from "unset_trace.c": - void unset_trace() - cdef struct LineTime: int64 code int lineno @@ -120,6 +137,7 @@ cdef struct LastTime: int f_lineno PY_LONG_LONG time + cdef inline int64 compute_line_hash(uint64 block_hash, uint64 linenum): """ Compute the hash used to store each line timing in an unordered_map. @@ -132,30 +150,49 @@ cdef inline int64 compute_line_hash(uint64 block_hash, uint64 linenum): return block_hash ^ linenum -if PY_VERSION_HEX < 0x030c00b1: # 3.12.0b1 - - def _sys_monitoring_register() -> None: - ... - - def _sys_monitoring_deregister() -> None: - ... - -else: - +if CAN_USE_SYS_MONITORING: def _is_main_thread() -> bool: return threading.current_thread() == threading.main_thread() - def _sys_monitoring_register() -> None: + 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.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) 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) + def label(code): """ @@ -176,6 +213,34 @@ def label(code): return (code.co_filename, code.co_firstlineno, code.co_name) +def find_cython_source_file(cython_func): + """ + Resolve the absolute path to a Cython function's source file. + + Returns: + result (str | None) + Cython source file if found, else :py:const:`None`. + """ + try: + compiled_module = cython_func.__globals__['__file__'] + except KeyError: # Shouldn't happen... + return None + rel_source_file = cython_func.__code__.co_filename + if os.path.isabs(rel_source_file): + if os.path.isfile(rel_source_file): + return rel_source_file + return None + prefix = os.path.dirname(compiled_module) + while True: + source_file = os.path.join(prefix, rel_source_file) + if os.path.isfile(source_file): + return source_file + next_prefix = os.path.dirname(prefix) + if next_prefix == prefix: # At the file-system root + return None + prefix = next_prefix + + cpdef _code_replace(func, co_code): """ Implements CodeType.replace for Python < 3.8 @@ -288,23 +353,54 @@ cdef class LineProfiler: warnings.warn("Could not extract a code object for the object %r" % (func,)) return - if code.co_code in self.dupes_map: - self.dupes_map[code.co_code] += [code] - # code hash already exists, so there must be a duplicate function. add no-op - co_padding : bytes = NOP_BYTES * (len(self.dupes_map[code.co_code]) + 1) - co_code = code.co_code + co_padding - CodeType = type(code) - code = _code_replace(func, co_code=co_code) - try: - func.__code__ = code - except AttributeError as e: - func.__func__.__code__ = code - else: - self.dupes_map[code.co_code] = [code] - # TODO: Since each line can be many bytecodes, this is kinda inefficient - # See if this can be sped up by not needing to iterate over every byte - for offset, byte in enumerate(code.co_code): - code_hash = compute_line_hash(hash((code.co_code)), PyCode_Addr2Line(code, offset)) + code_hashes = [] + if any(code.co_code): # Normal Python functions + if code.co_code in self.dupes_map: + self.dupes_map[code.co_code] += [code] + # code hash already exists, so there must be a duplicate + # function. add no-op + co_padding : bytes = NOP_BYTES * (len(self.dupes_map[code.co_code]) + 1) + co_code = code.co_code + co_padding + CodeType = type(code) + code = _code_replace(func, co_code=co_code) + try: + func.__code__ = code + except AttributeError as e: + func.__func__.__code__ = code + else: + self.dupes_map[code.co_code] = [code] + # TODO: Since each line can be many bytecodes, this is kinda + # inefficient + # See if this can be sped up by not needing to iterate over + # every byte + for offset, _ in enumerate(code.co_code): + code_hash = compute_line_hash( + hash((code.co_code)), + PyCode_Addr2Line(code, offset)) + code_hashes.append(code_hash) + else: # Cython functions have empty/zero bytecodes + if CANNOT_LINE_TRACE_CYTHON: + return + + from line_profiler.line_profiler import get_code_block + + lineno = code.co_firstlineno + if hasattr(func, '__code__'): + cython_func = func + else: + cython_func = func.__func__ + cython_source = find_cython_source_file(cython_func) + if not cython_source: # Can't find the source + return + nlines = len(get_code_block(cython_source, lineno)) + block_hash = hash(code) + for lineno in range(lineno, lineno + nlines): + code_hash = compute_line_hash(block_hash, lineno) + code_hashes.append(code_hash) + # We can't replace the code object on Cython functions, but + # we can *store* a copy with the correct metadata + code = code.replace(co_filename=cython_source) + for code_hash in code_hashes: if not self._c_code_map.count(code_hash): try: self.code_hash_map[code].append(code_hash) @@ -355,13 +451,15 @@ cdef class LineProfiler: self.disable_by_count() def enable(self): - # Register `line_profiler` with `sys.monitoring` in Python 3.12 - # and above; + # 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: - _sys_monitoring_register() - PyEval_SetTrace(python_trace_callback, instances) + if CAN_USE_SYS_MONITORING: + _sys_monitoring_register(instances) + else: + PyEval_SetTrace(legacy_trace_callback, instances) instances.add(self) @property @@ -416,12 +514,15 @@ cdef class LineProfiler: instances = self._active_instances self._c_last_time[threading.get_ident()].clear() instances.discard(self) - if not instances: - unset_trace() - # Deregister `line_profiler` with `sys.monitoring` in Python - # 3.12 and above; - # see: https://docs.python.org/3/library/sys.monitoring.html + # 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) def get_stats(self): """ @@ -460,21 +561,17 @@ cdef class LineProfiler: stats[key] = entries return LineStats(stats, self.timer_unit) + @cython.boundscheck(False) @cython.wraparound(False) -cdef extern int python_trace_callback(object instances, - PyFrameObject *py_frame, - int what, PyObject *arg): +cdef inline inner_trace_callback( + int is_line_event, object instances, object code, int lineno): """ - The PyEval_SetTrace() callback. - - References: - https://github.com/python/cpython/blob/de2a4036/Include/cpython/pystate.h#L16 + The basic building block for the trace callbacks. """ cdef object prof_ + cdef object bytecode = code.co_code cdef LineProfiler prof - cdef object code - cdef LineTime entry cdef LastTime old cdef int key cdef PY_LONG_LONG time @@ -482,39 +579,73 @@ cdef extern int python_trace_callback(object instances, cdef int64 code_hash cdef int64 block_hash cdef unordered_map[int64, LineTime] line_entries - cdef uint64 linenum - if 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 - block_hash = hash(get_frame_code(py_frame)) - - linenum = PyFrame_GetLineNumber(py_frame) - code_hash = compute_line_hash(block_hash, linenum) - - for prof_ in instances: - prof = prof_ - if not prof._c_code_map.count(code_hash): - continue - if not has_time: - time = hpTimer() - has_time = 1 - ident = threading.get_ident() - if prof._c_last_time[ident].count(block_hash): - old = prof._c_last_time[ident][block_hash] - 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].nhits += 1 - prof._c_code_map[code_hash][key].total_time += time - old.time - if what == PyTrace_LINE: - # Get the time again. This way, we don't record much time wasted - # in this function. - prof._c_last_time[ident][block_hash] = LastTime(linenum, 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)) + if any(bytecode): + block_hash = hash(bytecode) + else: # Cython functions have empty/zero bytecodes + block_hash = hash(code) + code_hash = compute_line_hash(block_hash, lineno) + + for prof_ in instances: + prof = prof_ + if not prof._c_code_map.count(code_hash): + continue + if not has_time: + time = hpTimer() + has_time = 1 + ident = threading.get_ident() + if prof._c_last_time[ident].count(block_hash): + old = prof._c_last_time[ident][block_hash] + 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].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. + 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) + +cdef extern int legacy_trace_callback( + object instances, PyFrameObject *py_frame, int what, PyObject *arg): + """ + The :c:func:`PyEval_SetTrace` callback. + + References: + https://github.com/python/cpython/blob/de2a4036/Include/cpython/\ +pystate.h#L16 + """ + if 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 + inner_trace_callback((what == PyTrace_LINE), + instances, + get_frame_code(py_frame), + PyFrame_GetLineNumber(py_frame)) return 0 diff --git a/line_profiler/line_profiler.py b/line_profiler/line_profiler.py index 5c7c40ea..8788844e 100755 --- a/line_profiler/line_profiler.py +++ b/line_profiler/line_profiler.py @@ -12,6 +12,7 @@ import sys import tempfile import types +import tokenize from argparse import ArgumentError, ArgumentParser from datetime import datetime @@ -38,6 +39,119 @@ def load_ipython_extension(ip): ip.register_magics(LineProfilerMagics) +def get_code_block(filename, lineno): + """ + Get the lines in the code block in a file starting from required + line number; understands Cython code. + + Args: + filename (Union[os.PathLike, str]) + Path to the source file. + lineno (int) + 1-indexed line number of the first line in the block. + + Returns: + lines (list[str]) + Newline-terminated string lines. + + Note: + This function makes use of :py:func:`inspect.getblock`, which is + public but undocumented API. That said, it has been in use in + this repo since 2008 (`fb60664`_), so we will continue using it + until we can't. + + .. _fb60664: https://github.com/pyutils/line_profiler/commit/\ +fb60664135296ba6061cfaa2bb66d4ba77964c53 + + + Example: + >>> from os.path import join + >>> from tempfile import TemporaryDirectory + >>> from textwrap import dedent + >>> + >>> + >>> def get_last_line(*args, **kwargs): + ... lines = get_code_block(*args, **kwargs) + ... return lines[-1].rstrip('\\n') + ... + >>> + >>> with TemporaryDirectory() as tmpdir: + ... fname = join(tmpdir, 'cython_source.pyx') + ... with open(fname, mode='w') as fobj: + ... print(dedent(''' + ... class NormalClass: # 1 + ... def __init__(self): # 2 + ... pass # 3 + ... + ... def normal_method(self, *args): # 5 + ... pass # 6 + ... + ... cdef class CythonClass: # 8 + ... cpdef cython_method(self): # 9 + ... pass # 10 + ... + ... property legacy_cython_prop: # 12 + ... def __get__(self): # 13 + ... return None # 14 + ... def __set__(self, value): # 15 + ... pass # 16 + ... + ... def normal_func(x, y, z): # 18 + ... with some_ctx(): # 19 + ... ... # 20 + ... + ... cdef cython_function( # 22 + ... int x, int y, int z): # 23 + ... ... # 24 + ... ''').strip('\\n'), + ... file=fobj) + ... # Vanilla Python code blocks: + ... # - `NormalClass` + ... assert get_last_line(fname, 1).endswith('# 6') + ... # - `NormalClass.__init__()` + ... assert get_last_line(fname, 2).endswith('# 3') + ... # - `normal_func()` + ... assert get_last_line(fname, 18).endswith('# 20') + ... # Cython code blocks: + ... # - `CythonClass` + ... assert get_last_line(fname, 8).endswith('# 16') + ... # - `CythonClass.cython_method()` + ... assert get_last_line(fname, 9).endswith('# 10') + ... # - `CythonClass.legacy_cython_prop` + ... assert get_last_line(fname, 12).endswith('# 16') + ... # - `cython_function()` + ... assert get_last_line(fname, 22).endswith('# 24') + """ + BlockFinder = inspect.BlockFinder + namespace = inspect.getblock.__globals__ + namespace['BlockFinder'] = _CythonBlockFinder + try: + return inspect.getblock(linecache.getlines(filename)[lineno - 1:]) + finally: + namespace['BlockFinder'] = BlockFinder + + +class _CythonBlockFinder(inspect.BlockFinder): + """ + Compatibility layer turning Cython-specific code blocks (``cdef``, + ``cpdef``, and legacy ``property`` declaration) into something that + is understood by :py:class:`inspect.BlockFinder`. + + Note: + This function makes use of :py:func:`inspect.BlockFinder`, which + is public but undocumented API. See similar caveat in + :py:func:`~.get_code_block`. + """ + def tokeneater(self, type, token, *args, **kwargs): + if ( + not self.started + and type == tokenize.NAME + and token in ('cdef', 'cpdef', 'property')): + # Fudge the token to get the desired 'scoping' behavior + token = 'def' + return super().tokeneater(type, token, *args, **kwargs) + + class _WrapperInfo: """ Helper object for holding the state of a wrapper function. @@ -462,8 +576,7 @@ def show_func(filename, start_lineno, func_name, timings, unit, if os.path.exists(filename): # Clear the cache to ensure that we get up-to-date results. linecache.clearcache() - all_lines = linecache.getlines(filename) - sublines = inspect.getblock(all_lines[start_lineno - 1:]) + sublines = get_code_block(filename, start_lineno) else: stream.write('\n') stream.write(f'Could not find file {filename}\n') diff --git a/line_profiler/profiler_mixin.py b/line_profiler/profiler_mixin.py index 4b2e3867..3bc98c1d 100644 --- a/line_profiler/profiler_mixin.py +++ b/line_profiler/profiler_mixin.py @@ -1,6 +1,7 @@ import functools import inspect import types +from sys import version_info from warnings import warn from .scoping_policy import ScopingPolicy @@ -19,15 +20,21 @@ types.MethodWrapperType, types.WrapperDescriptorType) +# 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 +_CANNOT_LINE_TRACE_CYTHON = (3, 12) <= version_info < (3, 13, 0, 'beta', 1) + def is_c_level_callable(func): """ Returns: func_is_c_level (bool): - Whether a callable is defined at the C(-ython) level (and is - thus non-profilable). + Whether a callable is defined at the C-level (and is thus + non-profilable). """ - return isinstance(func, C_LEVEL_CALLABLE_TYPES) or is_cython_callable(func) + return isinstance(func, C_LEVEL_CALLABLE_TYPES) def is_cython_callable(func): @@ -150,6 +157,8 @@ def _get_underlying_functions(cls, func, seen=None, stop_at_classes=False): seen.add(id(func)) if is_function(func): return [func] + if is_cython_callable(func): + return [] if _CANNOT_LINE_TRACE_CYTHON else [func] if is_c_level_callable(func): return [] # ... or a generic callable diff --git a/line_profiler/profiler_mixin.pyi b/line_profiler/profiler_mixin.pyi index 166cc39f..bd32a47a 100644 --- a/line_profiler/profiler_mixin.pyi +++ b/line_profiler/profiler_mixin.pyi @@ -120,8 +120,7 @@ else: CLevelCallable = TypeVar('CLevelCallable', BuiltinFunctionType, BuiltinMethodType, ClassMethodDescriptorType, MethodDescriptorType, - MethodWrapperType, WrapperDescriptorType, - CythonCallable) + MethodWrapperType, WrapperDescriptorType) def is_c_level_callable(func: Any) -> TypeIs[CLevelCallable]: diff --git a/line_profiler/unset_trace.c b/line_profiler/unset_trace.c deleted file mode 100644 index 68deb15b..00000000 --- a/line_profiler/unset_trace.c +++ /dev/null @@ -1,7 +0,0 @@ -/* Hack to hide an NULL from Cython. */ - -#include "Python.h" - -void unset_trace() { - PyEval_SetTrace(NULL, NULL); -} diff --git a/line_profiler/unset_trace.h b/line_profiler/unset_trace.h deleted file mode 100644 index 03df5d8f..00000000 --- a/line_profiler/unset_trace.h +++ /dev/null @@ -1 +0,0 @@ -void unset_trace(); diff --git a/setup.py b/setup.py index cec98395..d564fbf7 100755 --- a/setup.py +++ b/setup.py @@ -228,7 +228,8 @@ def run_cythonize(force=False): return cythonize( Extension( name="line_profiler._line_profiler", - sources=["line_profiler/_line_profiler.pyx", "line_profiler/timers.c", "line_profiler/unset_trace.c"], + sources=["line_profiler/_line_profiler.pyx", + "line_profiler/timers.c"], language="c++", define_macros=[("CYTHON_TRACE", (1 if os.getenv("DEV") == "true" else 0))], ), diff --git a/tests/cython_example/cython_example.pyx b/tests/cython_example/cython_example.pyx new file mode 100644 index 00000000..6d495528 --- /dev/null +++ b/tests/cython_example/cython_example.pyx @@ -0,0 +1,26 @@ +# cython: profile=True +# cython: linetrace=True +# distutils: define_macros=CYTHON_TRACE=1 + + +ctypedef long double Float + + +def cos(Float x, int n): # Start: cos + cdef Float neg_xsq = -x * x + cdef Float last_term = 1. + cdef Float result = 0. + for n in range(2, 2 * n, 2): + result += last_term + last_term *= neg_xsq / (n * (n - 1)) + return result + last_term # End: cos + + +cpdef sin(Float x, int n): # Start: sin + cdef Float neg_xsq = -x * x + cdef Float last_term = x + cdef Float result = 0. + for n in range(2, 2 * n, 2): + result += last_term + last_term *= neg_xsq / (n * (n + 1)) + return result + last_term # End: sin diff --git a/tests/cython_example/pyproject.toml b/tests/cython_example/pyproject.toml new file mode 100644 index 00000000..acaf4eca --- /dev/null +++ b/tests/cython_example/pyproject.toml @@ -0,0 +1,7 @@ +[build-system] +requires = ["setuptools", "Cython"] + +[project] +name = 'cython_example' +description = 'Sample Cython module to be profiled' +version = '0.0.0' diff --git a/tests/cython_example/setup.py b/tests/cython_example/setup.py new file mode 100644 index 00000000..3d6c83da --- /dev/null +++ b/tests/cython_example/setup.py @@ -0,0 +1,4 @@ +from setuptools import setup +from Cython.Build import cythonize + +setup(ext_modules=cythonize('cython_example.pyx')) diff --git a/tests/test_cython.py b/tests/test_cython.py new file mode 100644 index 00000000..fdbf7124 --- /dev/null +++ b/tests/test_cython.py @@ -0,0 +1,131 @@ +""" +Tests for profiling Cython code. +""" +import math +import os +import subprocess +import sys +from importlib import reload, import_module +from importlib.util import find_spec +from io import StringIO +from operator import methodcaller +from pathlib import Path +from types import ModuleType +from typing import Generator, Tuple +from uuid import uuid4 + +import pytest + +from line_profiler._line_profiler import ( + CANNOT_LINE_TRACE_CYTHON, find_cython_source_file) +from line_profiler.line_profiler import get_code_block, LineProfiler + + +def propose_name(prefix: str) -> Generator[str, None, None]: + while True: + yield '_'.join([prefix, *str(uuid4()).split('-')]) + + +def _install_cython_example( + tmp_path_factory: pytest.TempPathFactory, + editable: bool) -> Generator[Tuple[Path, str], None, None]: + """ + Install the example Cython module in a name-clash-free manner. + """ + source = Path(__file__).parent / 'cython_example' + assert source.is_dir() + module = next(name for name in propose_name('cython_example') + if not find_spec(name)) + replace = methodcaller('replace', 'cython_example', module) + pip = [sys.executable, '-m', 'pip'] + tmp_path = tmp_path_factory.mktemp('cython_example') + # Replace all references to `cython_example` with the actual module + # name and write to the tempdir + for prefix, _, files in os.walk(source): + dir_in = Path(prefix) + for fname in files: + _, ext = os.path.splitext(fname) + if ext not in {'.py', '.pyx', '.pxd', '.toml'}: + continue + dir_out = tmp_path.joinpath(*( + replace(part) for part in dir_in.relative_to(source).parts)) + dir_out.mkdir(exist_ok=True) + file_in = dir_in / fname + file_out = dir_out / replace(fname) + file_out.write_text(replace(file_in.read_text())) + # There should only be one Cython source file + cython_source, = tmp_path.glob('*.pyx') + pip_install = pip + ['install', '--verbose'] + if editable: + pip_install += ['--editable', str(tmp_path)] + else: + pip_install.append(str(tmp_path)) + try: + subprocess.run(pip_install).check_returncode() + subprocess.run(pip + ['list']).check_returncode() + yield cython_source, module + finally: + pip_uninstall = pip + ['uninstall', '--verbose', '--yes', module] + subprocess.run(pip_uninstall).check_returncode() + + +@pytest.fixture(scope='module') +def cython_example( + tmp_path_factory: pytest.TempPathFactory) -> Tuple[Path, ModuleType]: + """ + Install the example Cython module, yield the path to the Cython + source file and the corresponding module, uninstall it at teardown. + """ + # With editable installs, we need to refresh `sys.meta_path` before + # the installed module is available + for path, mod_name in _install_cython_example(tmp_path_factory, True): + reload(import_module('site')) + yield (path, import_module(mod_name)) + + +def test_recover_cython_source(cython_example: Tuple[Path, str]) -> None: + """ + Check that Cython sources are correctly located by + `line_profiler._line_profiler.find_cython_source_file()` and + `line_profiler.line_profiler.get_code_block()`. + """ + expected_source, module = cython_example + for func in module.cos, module.sin: + source = find_cython_source_file(func) + assert source + assert expected_source.samefile(source) + source_lines = get_code_block(source, func.__code__.co_firstlineno) + for line, prefix in [(source_lines[0], '# Start: '), + (source_lines[-1], '# End: ')]: + assert line.rstrip('\n').endswith(prefix + func.__name__) + + +@pytest.mark.skipif( + CANNOT_LINE_TRACE_CYTHON, + reason='Cannot line-trace Cython code in version ' + + '.'.join(str(v) for v in sys.version_info[:3])) +def test_profile_cython_source(cython_example: Tuple[Path, str]) -> None: + """ + Check that calls to Cython functions (built with the appropriate + compile-time options) can be profiled. + """ + prof_cos = LineProfiler() + prof_sin = LineProfiler() + + cos = prof_cos(cython_example[1].cos) + sin = prof_sin(cython_example[1].sin) + assert pytest.approx(cos(.125, 10)) == math.cos(.125) + assert pytest.approx(sin(2.5, 3)) == 2.5 - 2.5 ** 3 / 6 + 2.5 ** 5 / 120 + + for prof, func, expected_nhits in [ + (prof_cos, 'cos', 10), (prof_sin, 'sin', 3)]: + with StringIO() as fobj: + prof.print_stats(fobj) + result = fobj.getvalue() + print(result) + assert ('Function: ' + func) in result + nhits = 0 + for line in result.splitlines(): + if all(chunk in line for chunk in ('result', '+', 'last_term')): + nhits += int(line.split()[1]) + assert nhits == expected_nhits diff --git a/tests/test_line_profiler.py b/tests/test_line_profiler.py index e7df7b21..954c77b1 100644 --- a/tests/test_line_profiler.py +++ b/tests/test_line_profiler.py @@ -587,12 +587,10 @@ def __repr__(self): @pytest.mark.parametrize('decorate', [True, False]) def test_profiler_c_callable_no_op(decorate): """ - Test that the following are no-ops on C(-ython)-level callables: + Test that the following are no-ops on C-level callables: - Decoration (`.__call__()`): the callable is returned as-is. - `.add_callable()`: it returns 0. """ - CythonCallable = type(LineProfiler.enable) - assert not isinstance(LineProfiler.enable, types.FunctionType) profile = LineProfiler() for (func, Type) in [ @@ -601,8 +599,7 @@ def test_profiler_c_callable_no_op(decorate): (vars(int)['from_bytes'], types.ClassMethodDescriptorType), (str.split, types.MethodDescriptorType), ((1).__str__, types.MethodWrapperType), - (int.__repr__, types.WrapperDescriptorType), - (LineProfiler.enable, CythonCallable)]: + (int.__repr__, types.WrapperDescriptorType)]: assert isinstance(func, Type) if decorate: # Decoration is no-op assert profile(func) is func