Speed Up Worst-Case Overhead (#376)

* Speedups from avoiding re-resolution and threading.get_ident()

line_profiler/_line_profiler.pyx
    - Replaced repeated retrival of `prof._c_last_time[ident]` with a
      stored reference thereto

* Optimization: store pointer to the `LineTime` obj

* Fix GPT review suggestions 2 and 4

* Add comments for deref and hash_bytecode

* Refactor helpers into separate file

* add changelog note

---------

Co-authored-by: Terence S.-C. Tsang <[email protected]>
Co-authored-by: joncrall <[email protected]>

Author: 3 people

CHANGELOG.rst

@@ -5,6 +5,7 @@ Changes
 ~~~~~
 * FIX: ref-count leaks #372
 * ENH: Add support for building ABI3 wheels
+* FIX: mitigate speed regressions introduced in 5.0.0
 
 5.0.0
 ~~~~~

MANIFEST.in

@@ -9,6 +9,7 @@ recursive-include requirements *.txt
 recursive-include tests *.py
 recursive-include line_profiler *.txt
 recursive-include line_profiler *.pyx
+recursive-include line_profiler *.pyi
 recursive-include line_profiler *.pxd
 recursive-include line_profiler *.pyd
 recursive-include line_profiler *.c

build_wheels.sh

@@ -19,6 +19,8 @@ if ! which cibuildwheel ; then
 fi
 
 
-#pip wheel -w wheelhouse .
-# python -m build --wheel -o wheelhouse  #  line_profiler: +COMMENT_IF(binpy)
-cibuildwheel --config-file pyproject.toml --platform linux --archs x86_64  #  line_profiler: +UNCOMMENT_IF(binpy)
+# Build ABI3 wheels
+CIBW_CONFIG_SETTINGS="--build-option=--py-limited-api=cp38" CIBW_BUILD="cp38-*" cibuildwheel --config-file pyproject.toml --platform linux --archs x86_64
+
+# Build version-pinned wheels
+cibuildwheel --config-file pyproject.toml --platform linux --archs x86_64

clean.sh

@@ -5,6 +5,8 @@ rm -rf _skbuild
 rm -rf _line_profiler.c
 rm -rf *.so
 rm -rf line_profiler/_line_profiler.c
+rm -rf line_profiler/_line_profiler.cpp
+rm -rf line_profiler/*.html
 rm -rf line_profiler/*.so
 rm -rf build
 rm -rf line_profiler.egg-info

line_profiler/_line_profiler.pyx

@@ -18,6 +18,9 @@ from functools import wraps
 from sys import byteorder
 import sys
 cimport cython
+from cython.operator cimport dereference as deref
+from cpython.object cimport PyObject_Hash
+from cpython.bytes cimport PyBytes_AS_STRING, PyBytes_GET_SIZE
 from cpython.version cimport PY_VERSION_HEX
 from libc.stdint cimport int64_t
 
@@ -31,7 +34,13 @@ from warnings import warn
 from weakref import WeakSet
 
 from line_profiler._diagnostics import (
-    WRAP_TRACE, SET_FRAME_LOCAL_TRACE, USE_LEGACY_TRACE)
+    WRAP_TRACE, SET_FRAME_LOCAL_TRACE, USE_LEGACY_TRACE
+)
+
+from ._map_helpers cimport (
+    last_erase_if_present, line_ensure_entry, LastTime, LastTimeMap,
+    LineTime, LineTimeMap
+)
 
 
 NOP_VALUE: int = opcode.opmap['NOP']
@@ -69,6 +78,7 @@ cdef extern from "Python_wrapper.h":
     ctypedef struct PyObject
     ctypedef struct PyCodeObject
     ctypedef struct PyFrameObject
+    ctypedef Py_ssize_t Py_hash_t
     ctypedef long long PY_LONG_LONG
     ctypedef int (*Py_tracefunc)(
         object self, PyFrameObject *py_frame, int what, PyObject *arg)
@@ -93,6 +103,12 @@ cdef extern from "Python_wrapper.h":
     cdef int PyFrame_GetLineNumber(PyFrameObject *frame)
     cdef void Py_XDECREF(PyObject *o)
 
+    cdef unsigned long PyThread_get_thread_ident()
+
+ctypedef PyCodeObject *PyCodeObjectPtr
+#ctypedef unordered_map[int64, LastTime] LastTimeMap
+#ctypedef unordered_map[int64, LineTime] LineTimeMap
+
 cdef extern from "c_trace_callbacks.c":  # Legacy tracing
     ctypedef unsigned long long Py_uintptr_t
 
@@ -114,18 +130,18 @@ cdef extern from "timers.c":
     PY_LONG_LONG hpTimer()
     double hpTimerUnit()
 
-cdef struct LineTime:
-    int64 code
-    int lineno
-    PY_LONG_LONG total_time
-    long nhits
+#cdef struct LineTime:
+#    int64 code
+#    int lineno
+#    PY_LONG_LONG total_time
+#    long nhits
 
-cdef struct LastTime:
-    int f_lineno
-    PY_LONG_LONG time
+#cdef struct LastTime:
+#    int f_lineno
+#    PY_LONG_LONG time
 
 
-cdef inline int64 compute_line_hash(uint64 block_hash, uint64 linenum):
+cdef inline int64 compute_line_hash(uint64 block_hash, uint64 linenum) noexcept:
     """
     Compute the hash used to store each line timing in an unordered_map.
     This is fairly simple, and could use some improvement since linenum
@@ -298,7 +314,7 @@ cpdef _copy_local_sysmon_events(old_code, new_code):
     return new_code
 
 
-cpdef int _patch_events(int events, int before, int after):
+cpdef int _patch_events(int events, int before, int after) noexcept:
     """
     Patch ``events`` based on the differences between ``before`` and
     ``after``.
@@ -434,7 +450,7 @@ cdef class _SysMonitoringState:
             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):
+                            object loc_args, object other_args) noexcept:
         """
         Call the appropriate stored callback.  Also take care of the
         restoration of :py:mod:`sys.monitoring` callbacks, tool-ID lock,
@@ -550,7 +566,7 @@ sys.monitoring.html#monitoring-event-RERAISE
     """
     cdef TraceCallback *legacy_callback
     cdef _SysMonitoringState mon_state
-    cdef public object active_instances  # type: set[LineProfiler]
+    cdef public set active_instances  # type: set[LineProfiler]
     cdef int _wrap_trace
     cdef int _set_frame_local_trace
     cdef int recursion_guard
@@ -732,7 +748,7 @@ sys.monitoring.html#monitoring-event-RERAISE
             sys.monitoring.events.RERAISE, code, instruction_offset, exception)
 
     cdef void _handle_exit_event(
-            self, int event_id, object code, int offset, object obj):
+            self, int event_id, object code, int offset, object obj) noexcept:
         """
         Base for the frame-exit-event (e.g. via returning or yielding)
         callbacks passed to :py:func:`sys.monitoring.register_callback`.
@@ -746,7 +762,7 @@ sys.monitoring.html#monitoring-event-RERAISE
 
     cdef void _base_callback(
             self, int is_line_event, int event_id, object code, int lineno,
-            object loc_args, object other_args):
+            object loc_args, object other_args) noexcept:
         """
         Base for the various callbacks passed to
         :py:func:`sys.monitoring.register_callback`.
@@ -1030,9 +1046,9 @@ cdef class LineProfiler:
     .. _"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
+    cdef unordered_map[int64, LineTimeMap] _c_code_map
     # Mapping between thread-id and map of LastTime
-    cdef unordered_map[int64, unordered_map[int64, LastTime]] _c_last_time
+    cdef unordered_map[int64, LastTimeMap] _c_last_time
     cdef public list functions
     cdef public dict code_hash_map, dupes_map
     cdef public double timer_unit
@@ -1239,7 +1255,7 @@ datamodel.html#user-defined-functions
 
     property _manager:
         def __get__(self):
-            thread_id = threading.get_ident()
+            thread_id = PyThread_get_thread_ident()
             try:
                 return self._managers[thread_id]
             except KeyError:
@@ -1303,7 +1319,7 @@ datamodel.html#user-defined-functions
                 If no profiling data is available on the current thread.
         """
         try:
-            return (<dict>self._c_last_time)[threading.get_ident()]
+            return (<dict>self._c_last_time)[PyThread_get_thread_ident()]
         except KeyError as e:
             # We haven't actually profiled anything yet
             raise (KeyError('No profiling data on the current thread '
@@ -1349,7 +1365,7 @@ datamodel.html#user-defined-functions
         return py_last_time
 
     cpdef disable(self):
-        self._c_last_time[threading.get_ident()].clear()
+        self._c_last_time[PyThread_get_thread_ident()].clear()
         self._manager._handle_disable_event(self)
 
     def get_stats(self):
@@ -1387,56 +1403,79 @@ datamodel.html#user-defined-functions
 
 @cython.boundscheck(False)
 @cython.wraparound(False)
-cdef inline inner_trace_callback(
-        int is_line_event, object instances, object code, int lineno):
+cdef inline void inner_trace_callback(
+        int is_line_event, set instances, object code, int lineno):
     """
     The basic building block for the trace callbacks.
     """
-    cdef object prof_
-    cdef object bytecode = code.co_code
+    cdef LineProfiler prof_
     cdef LineProfiler prof
     cdef LastTime old
     cdef int key
-    cdef PY_LONG_LONG time
-    cdef int has_time = 0
+    cdef PY_LONG_LONG time = 0
+    cdef bint has_time = False
+    cdef bint has_last
     cdef int64 code_hash
-    cdef int64 block_hash
-    cdef unordered_map[int64, LineTime] line_entries
-
-    if any(bytecode):
-        block_hash = hash(bytecode)
-    else:  # Cython functions have empty/zero bytecodes
+    cdef object py_bytes_obj = code.co_code
+    cdef char* data = PyBytes_AS_STRING(py_bytes_obj)
+    cdef Py_ssize_t size = PyBytes_GET_SIZE(py_bytes_obj)
+    cdef unsigned long ident
+    cdef Py_hash_t block_hash
+    cdef LineTime* entry
+    cdef LineTimeMap* line_entries
+    cdef LastTimeMap* last_map
+
+    # Loop over every byte to check if any are not NULL
+    # if there are any non-NULL, that indicates we're profiling Python code
+    for i in range(size):
+        if data[i]:
+            # because we use Python functions like hash, we CANNOT mark this function as nogil
+            block_hash = hash(py_bytes_obj)
+            break
+    else:
+        # fallback for Cython functions
         block_hash = hash(code)
+
     code_hash = compute_line_hash(block_hash, lineno)
 
     for prof_ in instances:
+        # for some reason, doing this is much faster than just combining it into the above
+        # like doing "for prof in instances:" is far slower
         prof = <LineProfiler>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
+            has_time = True
+        ident = PyThread_get_thread_ident()
+        last_map = &(prof._c_last_time[ident])
+        # deref() is Cython's version of the -> accessor in C++. if we don't use deref then
+        # Cython thinks that when we index last_map,
+        # we want pointer indexing (which is not the case)
+        if deref(last_map).count(block_hash):
+            old = deref(last_map)[block_hash]
+            line_entries = &(prof._c_code_map[code_hash])
+            # Ensure that an entry exists in line_entries before accessing it
+            entry = line_ensure_entry(line_entries, old.f_lineno, code_hash)
+            # Note: explicitly `deref()`-ing here causes the new values
+            # to be assigned to a temp var;
+            # meanwhile, directly dot-accessing a pointer causes Cython
+            # to correctly write `ptr->attr = (ptr->attr + incr)`
+            entry.nhits += 1
+            entry.total_time += time - old.time
+            has_last = True
+        else:
+            has_last = False
         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):
+            deref(last_map)[block_hash] = LastTime(lineno, hpTimer())
+        elif deref(last_map).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))
+            last_erase_if_present(last_map, block_hash)
 
 
 cdef extern int legacy_trace_callback(

line_profiler/_map_helpers.pxd

@@ -0,0 +1,35 @@
+# cython: language_level=3
+# cython: legacy_implicit_noexcept=True
+# used in _line_profiler.pyx
+from libcpp.unordered_map cimport unordered_map
+from cython.operator cimport dereference as deref
+
+# long long int is at least 64 bytes assuming c99
+ctypedef long long int int64
+
+cdef extern from "Python_wrapper.h":
+    ctypedef long long PY_LONG_LONG
+
+cdef struct LastTime:
+    int f_lineno
+    PY_LONG_LONG time
+
+cdef struct LineTime:
+    long long code
+    int lineno
+    PY_LONG_LONG total_time
+    long nhits
+
+# Types used for mappings from code hash to last/line times.
+ctypedef unordered_map[int64, LastTime] LastTimeMap
+ctypedef unordered_map[int64, LineTime] LineTimeMap
+
+cdef inline void last_erase_if_present(LastTimeMap* m, int64 key) noexcept:
+    cdef LastTimeMap.iterator it = deref(m).find(key)
+    if it != deref(m).end():
+        deref(m).erase(it)
+
+cdef inline LineTime* line_ensure_entry(LineTimeMap* m, int lineno, long long code_hash) noexcept:
+    if not deref(m).count(lineno):
+        deref(m)[lineno] = LineTime(code_hash, lineno, 0, 0)
+    return &(deref(m)[lineno])

setup.py

@@ -231,6 +231,10 @@ def run_cythonize(force=False):
                     sources=["line_profiler/_line_profiler.pyx",
                              "line_profiler/timers.c",
                              "line_profiler/c_trace_callbacks.c"],
+                    # force a recompile if this changes
+                    depends=[
+                        "line_profiler/_map_helpers.pxd",
+                    ],
                     language="c++",
                     define_macros=[("CYTHON_TRACE", (1 if os.getenv("DEV") == "true" else 0))],
                 ),
@@ -240,7 +244,7 @@ def run_cythonize(force=False):
                     "legacy_implicit_noexcept": True,
                     "linetrace": (True if os.getenv("DEV") == "true" else False)
                 },
-                include_path=["line_profiler/python25.pxd"],
+                include_path=["line_profiler/python25.pxd", "line_profiler/_map_helpers.pxd"],
                 force=force,
                 nthreads=multiprocessing.cpu_count(),
             )
@@ -294,7 +298,6 @@ def run_cythonize(force=False):
     setupkw["classifiers"] = [
         'Development Status :: 5 - Production/Stable',
         'Intended Audience :: Developers',
-        'License :: OSI Approved :: BSD License',
         'Operating System :: OS Independent',
         'Programming Language :: C',
         'Programming Language :: Python',