FEAT: Profiler

.coveragerc

@@ -3,6 +3,7 @@ omit =
     main.py
     setup.py
     bcp_options.py
+    profiler/*
     tests/*
 
 [report]

README.md

@@ -167,7 +167,17 @@ provided by the bot. You will only need to do this once across all repos using o
 This project has adopted the [Microsoft Open Source Code of Conduct](https://opensource.microsoft.com/codeofconduct/).
 For more information see the [Code of Conduct FAQ](https://opensource.microsoft.com/codeofconduct/faq/) or
 contact [opencode@microsoft.com](mailto:opencode@microsoft.com) with any additional questions or comments.
-
+
+### Performance profiling (internal)
+
+The driver ships with an optional, compile-time-gated profiler that times both the
+Python and native (C++) layers of a query. The **native (C++) instrumentation is off
+by default and compiled out of released wheels**; the thin Python-layer markers
+(`perf_timer.py` and the `perf_phase(...)` calls) do ship, but are a no-op unless
+profiling is explicitly enabled. It is intended for contributors diagnosing where time
+goes on the execute/fetch paths. See [`profiler/README.md`](profiler/README.md) for how
+to build with profiling enabled and run it.
+
 ## License
 The mssql-python driver for SQL Server is licensed under the MIT license, except the dynamic-link libraries (DLLs) in the [libs](https://github.com/microsoft/mssql-python/tree/main/mssql_python_odbc/libs) folder 
 that are licensed under MICROSOFT SOFTWARE LICENSE TERMS.

mssql_python/perf_timer.py

@@ -0,0 +1,286 @@
+# Copyright (c) Microsoft Corporation.
+# Licensed under the MIT license.
+"""
+Lightweight phase-level profiling for the Python layer.
+
+Usage in cursor.py:
+    from mssql_python.perf_timer import perf_phase
+
+    with perf_phase("py::execute::param_type_detection"):
+        ...
+
+Control from profiler script:
+    from mssql_python.perf_timer import enable, disable, get_stats, reset
+
+Stats dict matches the C++ profiling format so both layers can be
+printed with the same reporter. Entries use a "py::" prefix to
+distinguish from C++ timers.
+"""
+
+import threading
+import time
+from contextlib import contextmanager
+from typing import NamedTuple
+
+
+class _Counter(NamedTuple):
+    calls: int
+    total_ns: int
+    min_ns: int
+    max_ns: int
+
+
+class _Event(NamedTuple):
+    name: str
+    start_ns: int
+    duration_ns: int
+
+
+_enabled = False
+_lock = threading.RLock()
+_local = threading.local()
+_window_start_ns = 0
+_stats: dict[str, _Counter] = {}
+_timeline: list[_Event] = []
+_timeline_enabled = False
+_epoch_ns: int = 0
+
+
+@contextmanager
+def _bookkeeping():
+    # GC can run SQL-cleanup finalizers during our own allocations. Suppress only
+    # recursive samples on this thread, not the cleanup or ordinary nested phases.
+    depth = getattr(_local, "depth", 0)
+    _local.depth = depth + 1
+    try:
+        yield
+    finally:
+        _local.depth = depth
+
+
+def enable():
+    global _enabled, _window_start_ns
+    with _bookkeeping():
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _window_start_ns = time.perf_counter_ns()
+            _enabled = True
+        finally:
+            release()
+
+
+def disable():
+    global _enabled
+    with _bookkeeping():
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _enabled = False
+        finally:
+            release()
+
+
+def is_enabled() -> bool:
+    return _enabled
+
+
+def reset():
+    global _window_start_ns, _stats, _timeline
+    with _bookkeeping():
+        stats, timeline = {}, []
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _window_start_ns = time.perf_counter_ns()
+            _stats = stats
+            _timeline = timeline
+        finally:
+            release()
+
+
+def reset_stats_only():
+    global _window_start_ns, _stats
+    with _bookkeeping():
+        stats = {}
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _window_start_ns = time.perf_counter_ns()
+            _stats = stats
+        finally:
+            release()
+
+
+def enable_timeline():
+    global _timeline_enabled, _epoch_ns, _timeline
+    # Clear any previously recorded events when (re)setting the epoch, so every
+    # event in _timeline shares the current epoch. Otherwise a second
+    # enable_timeline() without an intervening reset() would leave stale events
+    # whose offsets were computed from an older epoch, corrupting the sort.
+    with _bookkeeping():
+        timeline = []
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _timeline = timeline
+            _epoch_ns = time.perf_counter_ns()
+            _timeline_enabled = True
+        finally:
+            release()
+
+
+def disable_timeline():
+    global _timeline_enabled
+    with _bookkeeping():
+        release = _lock.release
+        _lock.acquire()
+        try:
+            _timeline_enabled = False
+        finally:
+            release()
+
+
+def get_timeline() -> list[dict]:
+    with _bookkeeping():
+        # Built-in container copies hold the GIL on supported CPython builds.
+        # Immutable entries stay stable; no profiler lock surrounds GC allocations.
+        snapshot = _timeline.copy()
+        return [
+            {
+                "name": ev.name,
+                "start_us": ev.start_ns // 1000,
+                "duration_us": ev.duration_ns // 1000,
+            }
+            for ev in snapshot
+        ]
+
+
+def get_stats() -> dict:
+    with _bookkeeping():
+        snapshot = _stats.copy()
+        out = {}
+        for name, s in snapshot.items():
+            # Keep fractional microseconds when converting accumulated samples.
+            out[name] = {
+                "calls": s.calls,
+                "total_us": s.total_ns / 1000.0,
+                "min_us": s.min_ns / 1000.0,
+                "max_us": s.max_ns / 1000.0,
+            }
+        return out
+
+
+class _NullPhase:
+    """No-op context manager returned by perf_phase when profiling is disabled.
+
+    A single shared instance is reused so the disabled path costs only a function
+    call plus two slot method calls, avoiding the generator + _GeneratorContextManager
+    allocation of an @contextmanager that every instrumented call site would
+    otherwise pay even when profiling is off.
+    """
+
+    __slots__ = ()
+
+    def __enter__(self):
+        return None
+
+    def __exit__(self, *exc):
+        return False
+
+
+class _Phase:
+    """Times one phase and records it on exit (used only when enabled).
+
+    Recording happens in __exit__, which always runs even if the wrapped block
+    raises, so an exception can't silently drop the sample and desync the Python
+    call counts from the C++ ones.
+    """
+
+    __slots__ = ("_name", "_t0")
+
+    def __init__(self, name: str):
+        self._name = name
+
+    def __enter__(self):
+        self._t0 = perf_start()
+        return None
+
+    def __exit__(self, *exc):
+        perf_stop(self._name, self._t0)
+        return False
+
+
+_NULL_PHASE = _NullPhase()
+
+
+def perf_phase(name: str):
+    if not _enabled:
+        return _NULL_PHASE
+    return _Phase(name)
+
+
+def perf_start() -> int:
+    if not _enabled:
+        return 0
+    return time.perf_counter_ns()
+
+
+def perf_stop(name: str, t0: int):
+    # t0 == 0 means perf_start() ran while disabled (or was never called); a
+    # falsy start has no valid interval, so record nothing rather than a bogus
+    # "now - 0" duration.
+    if not _enabled or not t0:
+        return
+    _record(name, time.perf_counter_ns() - t0, t0)
+
+
+def _record(name: str, elapsed: int, start_ns: int = 0):
+    if getattr(_local, "depth", 0):
+        return
+    with _bookkeeping():
+        # Prebind the no-argument release: RLock.__exit__ and method lookup can
+        # allocate before unlocking, which is unsafe around GC finalizers.
+        release = _lock.release
+        while True:
+            _lock.acquire()
+            try:
+                if not _enabled or (start_ns and start_ns < _window_start_ns):
+                    return
+                stats = _stats
+                entry = stats.get(name)
+                window = _window_start_ns
+                timeline = _timeline
+                epoch = _epoch_ns
+                record_event = _timeline_enabled and start_ns and start_ns >= epoch
+            finally:
+                release()
+
+            # Allocate before locking: GC may run a finalizer that waits for SQL
+            # on another thread, which must be able to finish its own recording.
+            updated = (
+                _Counter(1, elapsed, elapsed, elapsed)
+                if entry is None
+                else _Counter(
+                    entry.calls + 1,
+                    entry.total_ns + elapsed,
+                    min(entry.min_ns, elapsed),
+                    max(entry.max_ns, elapsed),
+                )
+            )
+            event = _Event(name, start_ns - epoch, elapsed) if record_event else None
+
+            _lock.acquire()
+            try:
+                # Revalidate after allocations and any callbacks they triggered.
+                if not _enabled or window != _window_start_ns or stats is not _stats:
+                    return
+                if stats.get(name) is not entry:
+                    continue
+                stats[name] = updated
+                # A timeline-only restart must not discard valid aggregate samples.
+                if event is not None and _timeline_enabled and timeline is _timeline:
+                    timeline.append(event)
+                return
+            finally:
+                release()

mssql_python/pybind/CMakeLists.txt

@@ -5,6 +5,10 @@ project(ddbc_bindings)
 set(CMAKE_CXX_STANDARD 17)
 set(CMAKE_CXX_STANDARD_REQUIRED ON)
 
+# Performance profiling instrumentation. OFF by default so released wheels ship
+# with zero profiler code. Turn on with -DENABLE_PROFILING=ON (dev/internal builds).
+option(ENABLE_PROFILING "Build with performance profiling instrumentation" OFF)
+
 # Enable verbose output to see actual compiler/linker commands
 set(CMAKE_VERBOSE_MAKEFILE ON CACHE BOOL "Verbose output" FORCE)
 
@@ -354,6 +358,12 @@ target_compile_definitions(ddbc_bindings PRIVATE
     NOMINMAX
 )
 
+# Emit ENABLE_PROFILING to the compiler only when the option is on.
+if(ENABLE_PROFILING)
+    message(STATUS "Building WITH performance profiling instrumentation")
+    target_compile_definitions(ddbc_bindings PRIVATE ENABLE_PROFILING)
+endif()
+
 # Add warning level flags for MSVC
 if(MSVC)
     target_compile_options(ddbc_bindings PRIVATE /W4 /WX)

mssql_python/pybind/build.bat

@@ -108,9 +108,20 @@ if errorlevel 1 (
     exit /b 1
 )
 
+REM Optional performance profiling instrumentation (off by default).
+REM Enable with: set ENABLE_PROFILING=1  (or ON) before running build.bat.
+REM Only "1"/"ON" enable it — a stray "set ENABLE_PROFILING=0" must NOT produce a
+REM profiling build (matches build.sh and avoids accidentally shipping one).
+set PROFILING_FLAG=
+if /I "%ENABLE_PROFILING%"=="1"  set "PROFILING_FLAG=-DENABLE_PROFILING=ON"
+if /I "%ENABLE_PROFILING%"=="ON" set "PROFILING_FLAG=-DENABLE_PROFILING=ON"
+if defined PROFILING_FLAG (
+    echo [MODE] Building WITH profiling instrumentation ^(ENABLE_PROFILING=%ENABLE_PROFILING%^)
+)
+
 REM Now invoke CMake with correct source path (options first, path last!)
-echo [DIAGNOSTIC] Running CMake configure with: cmake -A %PLATFORM_NAME% -DARCHITECTURE=%ARCH% "%SOURCE_DIR:~0,-1%"
-cmake -A %PLATFORM_NAME% -DARCHITECTURE=%ARCH% "%SOURCE_DIR:~0,-1%"
+echo [DIAGNOSTIC] Running CMake configure with: cmake -A %PLATFORM_NAME% -DARCHITECTURE=%ARCH% %PROFILING_FLAG% "%SOURCE_DIR:~0,-1%"
+cmake -A %PLATFORM_NAME% -DARCHITECTURE=%ARCH% %PROFILING_FLAG% "%SOURCE_DIR:~0,-1%"
 echo [DIAGNOSTIC] CMake configure exit code: %errorlevel%
 if errorlevel 1 (
     echo [ERROR] CMake configuration failed

mssql_python/pybind/build.sh

@@ -99,6 +99,14 @@ mkdir -p "${BUILD_DIR}"
 cd "${BUILD_DIR}"
 echo "[DIAGNOSTIC] Changed to build directory: ${BUILD_DIR}"
 
+# Optional performance profiling instrumentation (off by default).
+# Enable with: ENABLE_PROFILING=1 bash build.sh
+PROFILING_FLAG=""
+if [[ "${ENABLE_PROFILING:-}" == "1" || "${ENABLE_PROFILING:-}" == "ON" ]]; then
+    PROFILING_FLAG="-DENABLE_PROFILING=ON"
+    echo "[MODE] Building WITH profiling instrumentation (ENABLE_PROFILING=ON)"
+fi
+
 # Configure CMake (with Clang coverage instrumentation on Linux only - codecov is not supported for macOS)
 echo "[DIAGNOSTIC] Running CMake configure"
 if [[ "$COVERAGE_MODE" == "true" && "$OS" == "Linux" ]]; then
@@ -108,14 +116,15 @@ if [[ "$COVERAGE_MODE" == "true" && "$OS" == "Linux" ]]; then
           -DCMAKE_CXX_COMPILER=clang++ \
           -DCMAKE_CXX_FLAGS="-fprofile-instr-generate -fcoverage-mapping" \
           -DCMAKE_C_FLAGS="-fprofile-instr-generate -fcoverage-mapping" \
+          $PROFILING_FLAG \
           "${SOURCE_DIR}"
 else
     if [[ "$OS" == "macOS" ]]; then
         echo "[ACTION] Configuring for macOS (default build)"
-        cmake -DMACOS_STRING_FIX=ON "${SOURCE_DIR}"
+        cmake -DMACOS_STRING_FIX=ON $PROFILING_FLAG "${SOURCE_DIR}"
     else
         echo "[ACTION] Configuring for Linux with architecture: $DETECTED_ARCH"
-        cmake -DARCHITECTURE="$DETECTED_ARCH" "${SOURCE_DIR}"
+        cmake -DARCHITECTURE="$DETECTED_ARCH" $PROFILING_FLAG "${SOURCE_DIR}"
     fi
 fi