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,181 @@
+# 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 time
+
+_enabled = False
+_stats: dict[str, dict] = {}
+_timeline: list[dict] = []
+_timeline_enabled = False
+_epoch_ns: int = 0
+
+
+def enable():
+    global _enabled
+    _enabled = True
+
+
+def disable():
+    global _enabled
+    _enabled = False
+
+
+def is_enabled() -> bool:
+    return _enabled
+
+
+def reset():
+    _stats.clear()
+    _timeline.clear()
+
+
+def reset_stats_only():
+    _stats.clear()
+
+
+def enable_timeline():
+    global _timeline_enabled, _epoch_ns
+    # 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.
+    _timeline.clear()
+    _epoch_ns = time.perf_counter_ns()
+    _timeline_enabled = True
+
+
+def disable_timeline():
+    global _timeline_enabled
+    _timeline_enabled = False
+
+
+def get_timeline() -> list[dict]:
+    return [
+        {
+            "name": ev["name"],
+            "start_us": ev["start_ns"] // 1000,
+            "duration_us": ev["duration_ns"] // 1000,
+        }
+        for ev in _timeline
+    ]
+
+
+def get_stats() -> dict:
+    out = {}
+    for name, s in _stats.items():
+        # Divide accumulated ns to us only here (never per-sample) and keep
+        # fractional us so sub-microsecond phases do not truncate to zero.
+        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 = time.perf_counter_ns()
+        return None
+
+    def __exit__(self, *exc):
+        _record(self._name, time.perf_counter_ns() - self._t0, 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):
+    entry = _stats.get(name)
+    if entry is None:
+        _stats[name] = {
+            "calls": 1,
+            "total_ns": elapsed,
+            "min_ns": elapsed,
+            "max_ns": elapsed,
+        }
+    else:
+        entry["calls"] += 1
+        entry["total_ns"] += elapsed
+        if elapsed < entry["min_ns"]:
+            entry["min_ns"] = elapsed
+        if elapsed > entry["max_ns"]:
+            entry["max_ns"] = elapsed
+
+    if _timeline_enabled and start_ns:
+        _timeline.append(
+            {
+                "name": name,
+                "start_ns": start_ns - _epoch_ns,
+                "duration_ns": elapsed,
+            }
+        )

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