diff --git a/.coveragerc b/.coveragerc index 9b922851..72fc8dea 100644 --- a/.coveragerc +++ b/.coveragerc @@ -3,6 +3,7 @@ omit = main.py setup.py bcp_options.py + profiler/* tests/* [report] diff --git a/README.md b/README.md index e67689ff..d24937dc 100644 --- a/README.md +++ b/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. diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index 605120bf..8c60f9a2 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -29,6 +29,7 @@ DatabaseError, ) from mssql_python.row import Row +from mssql_python.perf_timer import perf_phase, perf_start, perf_stop from mssql_python import get_settings from mssql_python.parameter_helper import ( detect_and_convert_parameters, @@ -1731,34 +1732,37 @@ def execute( # pylint: disable=too-many-locals,too-many-branches,too-many-state # it will be unwrapped for parameter binding. This means you cannot # pass a tuple as a single parameter value (but SQL Server doesn't # support tuple types as parameter values anyway). - if parameters: - # Check if single parameter is a nested container that should be unwrapped - # e.g., execute("SELECT ?", (value,)) vs execute("SELECT ?, ?", ((1, 2),)) - if isinstance(parameters, tuple) and len(parameters) == 1: - if isinstance(parameters[0], (tuple, list, dict)): - actual_params = parameters[0] - elif isinstance(parameters[0], Row): - # A Row (e.g. from fetchone()) is a sequence of column values. - # Normalize it to a tuple so the downstream binding logic, which - # only handles tuple/list/dict, can unwrap it into individual - # parameters instead of treating the whole Row as one value. - actual_params = tuple(parameters[0]) + with perf_phase("py::execute::param_unpack"): + if parameters: + # Check if single parameter is a nested container that should be unwrapped + # e.g., execute("SELECT ?", (value,)) vs execute("SELECT ?, ?", ((1, 2),)) + if isinstance(parameters, tuple) and len(parameters) == 1: + if isinstance(parameters[0], (tuple, list, dict)): + actual_params = parameters[0] + elif isinstance(parameters[0], Row): + # A Row (e.g. from fetchone()) is a sequence of column values. + # Normalize it to a tuple so the downstream binding logic, which + # only handles tuple/list/dict, can unwrap it into individual + # parameters instead of treating the whole Row as one value. + actual_params = tuple(parameters[0]) + else: + actual_params = parameters else: actual_params = parameters - else: - actual_params = parameters - # Skip detect_and_convert_parameters when re-executing the same SQL — - # the parameter style (qmark vs pyformat) won't change between calls. - if operation == self.last_executed_stmt and isinstance(actual_params, (tuple, list)): - parameters = list(actual_params) + # Skip detect_and_convert_parameters when re-executing the same SQL — + # the parameter style (qmark vs pyformat) won't change between calls. + if operation == self.last_executed_stmt and isinstance( + actual_params, (tuple, list) + ): + parameters = list(actual_params) + else: + operation, converted_params = detect_and_convert_parameters( + operation, actual_params + ) + parameters = list(converted_params) else: - operation, converted_params = detect_and_convert_parameters( - operation, actual_params - ) - parameters = list(converted_params) - else: - parameters = [] + parameters = [] # Getting encoding setting encoding_settings = self._get_encoding_settings() @@ -1782,18 +1786,19 @@ def execute( # pylint: disable=too-many-locals,too-many-branches,too-many-state self.is_stmt_prepared = [False] effective_use_prepare = use_prepare and not same_sql - if parameters: - ret = ddbc_bindings.DDBCSQLExecute( - self.hstmt, - operation, - parameters, - self._inputsizes, - self.is_stmt_prepared, - effective_use_prepare, - encoding_settings, - ) - else: - ret = ddbc_bindings.DDBCSQLExecDirect(self.hstmt, operation) + with perf_phase("py::execute::cpp_call"): + if parameters: + ret = ddbc_bindings.DDBCSQLExecute( + self.hstmt, + operation, + parameters, + self._inputsizes, + self.is_stmt_prepared, + effective_use_prepare, + encoding_settings, + ) + else: + ret = ddbc_bindings.DDBCSQLExecDirect(self.hstmt, operation) # Check return code try: @@ -1804,24 +1809,27 @@ def execute( # pylint: disable=too-many-locals,too-many-branches,too-many-state self._reset_cursor() raise - self._capture_diagnostics(ret) + # Capture any diagnostic messages (SQL_SUCCESS_WITH_INFO, etc.) + with perf_phase("py::execute::diag_records"): + self._capture_diagnostics(ret) self.last_executed_stmt = operation - # Update rowcount after execution - # TODO: rowcount return code from SQL needs to be handled - self.rowcount = ddbc_bindings.DDBCSQLRowCount(self.hstmt) + with perf_phase("py::execute::post_execute"): + # Update rowcount after execution + # TODO: rowcount return code from SQL needs to be handled + self.rowcount = ddbc_bindings.DDBCSQLRowCount(self.hstmt) - # Initialize description after execution - # After successful execution, initialize description if there are results - column_metadata = [] - try: - ddbc_bindings.DDBCSQLDescribeCol(self.hstmt, column_metadata) - self._initialize_description(column_metadata) - except Exception as e: # pylint: disable=broad-exception-caught - # If describe fails, it's likely there are no results (e.g., for INSERT) - self.description = None - self._column_sql_types = None + # Initialize description after execution + # After successful execution, initialize description if there are results + column_metadata = [] + try: + ddbc_bindings.DDBCSQLDescribeCol(self.hstmt, column_metadata) + self._initialize_description(column_metadata) + except Exception as e: # pylint: disable=broad-exception-caught + # If describe fails, it's likely there are no results (e.g., for INSERT) + self.description = None + self._column_sql_types = None # Reset rownumber for new result set (only for SELECT statements) if self.description: # If we have column descriptions, it's likely a SELECT @@ -2470,6 +2478,7 @@ def executemany( # pylint: disable=too-many-locals,too-many-branches,too-many-s ) # Prepare parameter type information + _t0 = perf_start() for col_index in range(param_count): column = ( [row[col_index] for row in seq_of_parameters] @@ -2616,6 +2625,7 @@ def executemany( # pylint: disable=too-many-locals,too-many-branches,too-many-s parameters_type.append(paraminfo) if paraminfo.isDAE: any_dae = True + perf_stop("py::executemany::param_type_detection", _t0) if any_dae: logger.debug( @@ -2627,6 +2637,7 @@ def executemany( # pylint: disable=too-many-locals,too-many-branches,too-many-s # Process parameters into column-wise format with possible type conversions # First, convert any Decimal types as needed for NUMERIC/DECIMAL columns + _conv_t0 = perf_start() processed_parameters = [] for row_index, row in enumerate(seq_of_parameters): processed_row = list(row) @@ -2677,9 +2688,13 @@ def executemany( # pylint: disable=too-many-locals,too-many-branches,too-many-s except Exception: # pylint: disable=broad-exception-caught raise ValueError(err_msg) from None processed_parameters.append(processed_row) + perf_stop("py::executemany::param_conversion", _conv_t0) # Now transpose the processed parameters - columnwise_params, row_count = self._transpose_rowwise_to_columnwise(processed_parameters) + with perf_phase("py::executemany::param_processing"): + columnwise_params, row_count = self._transpose_rowwise_to_columnwise( + processed_parameters + ) # Get encoding settings encoding_settings = self._get_encoding_settings() @@ -2695,13 +2710,20 @@ def executemany( # pylint: disable=too-many-locals,too-many-branches,too-many-s len(parameters_type), ) - ret = ddbc_bindings.SQLExecuteMany( - self.hstmt, operation, columnwise_params, parameters_type, row_count, encoding_settings - ) + with perf_phase("py::executemany::cpp_call"): + ret = ddbc_bindings.SQLExecuteMany( + self.hstmt, + operation, + columnwise_params, + parameters_type, + row_count, + encoding_settings, + ) # Capture any diagnostic messages after execution - if self.hstmt: - self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) + with perf_phase("py::executemany::diag_records"): + if self.hstmt: + self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) try: check_error(ddbc_sql_const.SQL_HANDLE_STMT.value, self.hstmt, ret) @@ -2756,16 +2778,18 @@ def fetchone(self) -> Union[None, Row]: # Fetch raw data row_data = [] try: - ret = ddbc_bindings.DDBCSQLFetchOne( - self.hstmt, - row_data, - char_decoding.get("encoding", "utf-16le"), - wchar_decoding.get("encoding", "utf-16le"), - char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), - ) + with perf_phase("py::fetchone::cpp_call"): + ret = ddbc_bindings.DDBCSQLFetchOne( + self.hstmt, + row_data, + char_decoding.get("encoding", "utf-16le"), + wchar_decoding.get("encoding", "utf-16le"), + char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), + ) - if self.hstmt: - self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) + with perf_phase("py::fetchone::diag_records"): + if self.hstmt: + self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) if ret == ddbc_sql_const.SQL_NO_DATA.value: # No more data available @@ -2785,17 +2809,18 @@ def fetchone(self) -> Union[None, Row]: # Get column and converter maps column_map, converter_map, column_map_lower = self._get_column_and_converter_maps() - return Row( - row_data, - column_map, - cursor=self, - converter_map=converter_map, - uuid_str_indices=self._uuid_str_indices, - column_map_lower=column_map_lower, - ) - except Exception as e: + with perf_phase("py::fetchone::row_wrap"): + return Row( + row_data, + column_map, + cursor=self, + converter_map=converter_map, + uuid_str_indices=self._uuid_str_indices, + column_map_lower=column_map_lower, + ) + except Exception: # On error, don't increment rownumber - rethrow the error - raise e + raise def fetchmany(self, size: Optional[int] = None) -> List[Row]: """ @@ -2823,17 +2848,19 @@ def fetchmany(self, size: Optional[int] = None) -> List[Row]: # Fetch raw data rows_data = [] try: - ret = ddbc_bindings.DDBCSQLFetchMany( - self.hstmt, - rows_data, - size, - char_decoding.get("encoding", "utf-16le"), - wchar_decoding.get("encoding", "utf-16le"), - char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), - ) + with perf_phase("py::fetchmany::cpp_call"): + ret = ddbc_bindings.DDBCSQLFetchMany( + self.hstmt, + rows_data, + size, + char_decoding.get("encoding", "utf-16le"), + wchar_decoding.get("encoding", "utf-16le"), + char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), + ) - if self.hstmt: - self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) + with perf_phase("py::fetchmany::diag_records"): + if self.hstmt: + self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) # Update rownumber for the number of rows actually fetched if rows_data and self._has_result_set: @@ -2852,20 +2879,21 @@ def fetchmany(self, size: Optional[int] = None) -> List[Row]: # Convert raw data to Row objects uuid_idx = self._uuid_str_indices - return [ - Row( - row_data, - column_map, - cursor=self, - converter_map=converter_map, - uuid_str_indices=uuid_idx, - column_map_lower=column_map_lower, - ) - for row_data in rows_data - ] - except Exception as e: + with perf_phase("py::fetchmany::row_wrap"): + return [ + Row( + row_data, + column_map, + cursor=self, + converter_map=converter_map, + uuid_str_indices=uuid_idx, + column_map_lower=column_map_lower, + ) + for row_data in rows_data + ] + except Exception: # On error, don't increment rownumber - rethrow the error - raise e + raise def fetchall(self) -> List[Row]: """ @@ -2884,19 +2912,21 @@ def fetchall(self) -> List[Row]: # Fetch raw data rows_data = [] try: - ret = ddbc_bindings.DDBCSQLFetchAll( - self.hstmt, - rows_data, - char_decoding.get("encoding", "utf-16le"), - wchar_decoding.get("encoding", "utf-16le"), - char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), - ) + with perf_phase("py::fetchall::cpp_call"): + ret = ddbc_bindings.DDBCSQLFetchAll( + self.hstmt, + rows_data, + char_decoding.get("encoding", "utf-16le"), + wchar_decoding.get("encoding", "utf-16le"), + char_decoding.get("ctype", ddbc_sql_const.SQL_WCHAR.value), + ) # Check for errors check_error(ddbc_sql_const.SQL_HANDLE_STMT.value, self.hstmt, ret) - if self.hstmt: - self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) + with perf_phase("py::fetchall::diag_records"): + if self.hstmt: + self.messages.extend(ddbc_bindings.DDBCSQLGetAllDiagRecords(self.hstmt)) # Update rownumber for the number of rows actually fetched if rows_data and self._has_result_set: @@ -2914,20 +2944,21 @@ def fetchall(self) -> List[Row]: # Convert raw data to Row objects uuid_idx = self._uuid_str_indices - return [ - Row( - row_data, - column_map, - cursor=self, - converter_map=converter_map, - uuid_str_indices=uuid_idx, - column_map_lower=column_map_lower, - ) - for row_data in rows_data - ] - except Exception as e: + with perf_phase("py::fetchall::row_wrap"): + return [ + Row( + row_data, + column_map, + cursor=self, + converter_map=converter_map, + uuid_str_indices=uuid_idx, + column_map_lower=column_map_lower, + ) + for row_data in rows_data + ] + except Exception: # On error, don't increment rownumber - rethrow the error - raise e + raise def arrow_batch(self, batch_size: int = 8192) -> "pyarrow.RecordBatch": """ diff --git a/mssql_python/perf_timer.py b/mssql_python/perf_timer.py new file mode 100644 index 00000000..f4eae500 --- /dev/null +++ b/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, + } + ) diff --git a/mssql_python/pybind/CMakeLists.txt b/mssql_python/pybind/CMakeLists.txt index c75eb23e..2ce26425 100644 --- a/mssql_python/pybind/CMakeLists.txt +++ b/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) diff --git a/mssql_python/pybind/build.bat b/mssql_python/pybind/build.bat index d6b8b5c8..731a9c90 100644 --- a/mssql_python/pybind/build.bat +++ b/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 diff --git a/mssql_python/pybind/build.sh b/mssql_python/pybind/build.sh index 2afec206..05bc6956 100755 --- a/mssql_python/pybind/build.sh +++ b/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 diff --git a/mssql_python/pybind/connection/connection.cpp b/mssql_python/pybind/connection/connection.cpp index 00cf910e..8ccee11a 100644 --- a/mssql_python/pybind/connection/connection.cpp +++ b/mssql_python/pybind/connection/connection.cpp @@ -16,6 +16,7 @@ // Logging uses LOG() macro for all diagnostic output #include "logger_bridge.hpp" +#include "performance_counter.hpp" static SqlHandlePtr getEnvHandle() { static SqlHandlePtr envHandle = []() -> SqlHandlePtr { @@ -47,6 +48,7 @@ static SqlHandlePtr getEnvHandle() { //------------------------------------------------------------------------------------------------- Connection::Connection(const std::u16string& conn_str, bool use_pool) : _connStr(conn_str), _autocommit(false), _fromPool(use_pool) { + PERF_TIMER("Connection::Connection"); allocateDbcHandle(); } @@ -56,6 +58,7 @@ Connection::~Connection() { // Allocates connection handle void Connection::allocateDbcHandle() { + PERF_TIMER("Connection::allocateDbcHandle"); // Fetch/initialize the shared env handle without holding the GIL (#671): // its first-time initialization runs under a C++ static-init guard and // emits log records; a thread waiting on that guard while holding the GIL @@ -72,6 +75,7 @@ void Connection::allocateDbcHandle() { } void Connection::connect(const py::dict& attrs_before) { + PERF_TIMER("Connection::connect"); LOG("Connecting to database"); // Apply access token before connect if (!attrs_before.is_none() && py::len(attrs_before) > 0) { @@ -89,6 +93,7 @@ void Connection::connect(const py::dict& attrs_before) { // and SQL Server authentication — all pure I/O that doesn't need the GIL. // This allows other Python threads to run concurrently. py::gil_scoped_release release; + PERF_TIMER("Connection::connect::SQLDriverConnect_call"); ret = SQLDriverConnect_ptr(_dbcHandle->get(), nullptr, connStrPtr, SQL_NTS, nullptr, 0, nullptr, SQL_DRIVER_NOPROMPT); } @@ -97,6 +102,7 @@ void Connection::connect(const py::dict& attrs_before) { } void Connection::disconnect() { + PERF_TIMER("Connection::disconnect"); // Determine GIL state once, up front. disconnect() runs both from // pybind11-bound methods (GIL held) and from GIL-less destructor / shutdown // paths: Connection::~Connection() dropping the last shared_ptr, or teardown @@ -207,6 +213,7 @@ void Connection::checkError(SQLRETURN ret) const { } void Connection::commit() { + PERF_TIMER("Connection::commit"); if (!_dbcHandle) { ThrowStdException("Connection handle not allocated"); } @@ -222,6 +229,7 @@ void Connection::commit() { } void Connection::rollback() { + PERF_TIMER("Connection::rollback"); if (!_dbcHandle) { ThrowStdException("Connection handle not allocated"); } @@ -237,6 +245,7 @@ void Connection::rollback() { } void Connection::setAutocommit(bool enable) { + PERF_TIMER("Connection::setAutocommit"); if (!_dbcHandle) { ThrowStdException("Connection handle not allocated"); } @@ -275,6 +284,7 @@ bool Connection::getAutocommit() const { } SqlHandlePtr Connection::allocStatementHandle() { + PERF_TIMER("Connection::allocStatementHandle"); if (!_dbcHandle) { ThrowStdException("Connection handle not allocated"); } @@ -618,6 +628,7 @@ ConnectionHandle::ConnectionHandle(const std::u16string& connStr, bool usePool, const py::dict& attrsBefore, const std::u16string& poolKey, const py::object& tokenFactory) : _usePool(usePool), _connStr(connStr), _poolKey(poolKey.empty() ? connStr : poolKey) { + PERF_TIMER("ConnectionHandle::ConnectionHandle"); if (_usePool) { _conn = ConnectionPoolManager::getInstance().acquireConnection(_connStr, attrsBefore, _poolKey, tokenFactory); @@ -653,6 +664,7 @@ ConnectionHandle::~ConnectionHandle() { } void ConnectionHandle::close() { + PERF_TIMER("ConnectionHandle::close"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -665,6 +677,7 @@ void ConnectionHandle::close() { } void ConnectionHandle::commit() { + PERF_TIMER("ConnectionHandle::commit"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -672,6 +685,7 @@ void ConnectionHandle::commit() { } void ConnectionHandle::rollback() { + PERF_TIMER("ConnectionHandle::rollback"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -679,6 +693,7 @@ void ConnectionHandle::rollback() { } void ConnectionHandle::setAutocommit(bool enabled) { + PERF_TIMER("ConnectionHandle::setAutocommit"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -693,6 +708,7 @@ bool ConnectionHandle::getAutocommit() const { } SqlHandlePtr ConnectionHandle::allocStatementHandle() { + PERF_TIMER("ConnectionHandle::allocStatementHandle"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -757,6 +773,7 @@ py::object Connection::getInfo(SQLUSMALLINT infoType) const { } py::object ConnectionHandle::getInfo(SQLUSMALLINT infoType) const { + PERF_TIMER("ConnectionHandle::getInfo"); if (!_conn) { ThrowStdException("Connection object is not initialized"); } @@ -764,6 +781,7 @@ py::object ConnectionHandle::getInfo(SQLUSMALLINT infoType) const { } void ConnectionHandle::setAttr(int attribute, py::object value) { + PERF_TIMER("ConnectionHandle::setAttr"); if (!_conn) { ThrowStdException("Connection not established"); } diff --git a/mssql_python/pybind/connection/connection_pool.cpp b/mssql_python/pybind/connection/connection_pool.cpp index c4c3418d..831a01db 100644 --- a/mssql_python/pybind/connection/connection_pool.cpp +++ b/mssql_python/pybind/connection/connection_pool.cpp @@ -10,6 +10,7 @@ // Logging uses LOG() macro for all diagnostic output #include "logger_bridge.hpp" +#include "performance_counter.hpp" // Refresh threshold for expiry-aware checkout: a pooled connection whose access // token expires within this many seconds is discarded and reopened with a fresh @@ -58,6 +59,7 @@ ConnectionPool::ConnectionPool(size_t max_size, int idle_timeout_secs) std::shared_ptr ConnectionPool::acquire(const std::u16string& connStr, const py::dict& attrs_before, const py::object& token_factory) { + PERF_TIMER("ConnectionPool::acquire"); std::vector> to_disconnect; std::shared_ptr valid_conn = nullptr; bool needs_connect = false; @@ -302,6 +304,7 @@ std::shared_ptr ConnectionPool::acquire(const std::u16string& connSt } void ConnectionPool::release(std::shared_ptr conn) { + PERF_TIMER("ConnectionPool::release"); bool should_disconnect = false; { std::lock_guard lock(_mutex); @@ -358,6 +361,7 @@ bool ConnectionPool::canEvict() { } void ConnectionPool::close() { + PERF_TIMER("ConnectionPool::close"); std::vector> to_close; { std::lock_guard lock(_mutex); @@ -385,6 +389,7 @@ std::shared_ptr ConnectionPoolManager::acquireConnection(const std:: const py::dict& attrs_before, const std::u16string& pool_key, const py::object& token_factory) { + PERF_TIMER("ConnectionPoolManager::acquireConnection"); // Key the pool by pool_key when provided (identity-aware), // else fall back to the connection string (legacy behavior). const std::u16string& key = pool_key.empty() ? connStr : pool_key; diff --git a/mssql_python/pybind/ddbc_bindings.cpp b/mssql_python/pybind/ddbc_bindings.cpp index 9908d842..26948ee8 100644 --- a/mssql_python/pybind/ddbc_bindings.cpp +++ b/mssql_python/pybind/ddbc_bindings.cpp @@ -8,6 +8,7 @@ #include "connection/connection.h" #include "connection/connection_pool.h" #include "logger_bridge.hpp" +#include "performance_counter.hpp" #include "param_detect.hpp" #include "py_ref.hpp" #include "py_type_cache.hpp" @@ -453,6 +454,7 @@ SQLRETURN BindParameters(SqlHandle& handle, SQLHANDLE hStmt, const py::list& par std::vector& paramInfos, std::vector>& paramBuffers, const std::string& charEncoding = "utf-8") { + PERF_TIMER("BindParameters"); LOG("BindParameters: Starting parameter binding for statement handle %p " "with %zu parameters", (void*)hStmt, params.size()); @@ -858,12 +860,16 @@ SQLRETURN BindParameters(SqlHandle& handle, SQLHANDLE hStmt, const py::list& par } } assert(SQLBindParameter_ptr && SQLGetStmtAttr_ptr && SQLSetDescField_ptr); - RETCODE rc = SQLBindParameter_ptr( - hStmt, static_cast(paramIndex + 1), /* 1-based indexing */ - static_cast(paramInfo.inputOutputType), - static_cast(paramInfo.paramCType), - static_cast(paramInfo.paramSQLType), paramInfo.columnSize, - paramInfo.decimalDigits, dataPtr, bufferLength, strLenOrIndPtr); + RETCODE rc; + { + PERF_TIMER("BindParameters::SQLBindParameter_call"); + rc = SQLBindParameter_ptr( + hStmt, static_cast(paramIndex + 1), /* 1-based indexing */ + static_cast(paramInfo.inputOutputType), + static_cast(paramInfo.paramCType), + static_cast(paramInfo.paramSQLType), paramInfo.columnSize, + paramInfo.decimalDigits, dataPtr, bufferLength, strLenOrIndPtr); + } if (!SQL_SUCCEEDED(rc)) { LOG("BindParameters: SQLBindParameter failed for param[%d] - " "SQLRETURN=%d, C_Type=%d, SQL_Type=%d", @@ -1501,6 +1507,7 @@ DriverLoader& DriverLoader::getInstance() { } void DriverLoader::loadDriver() { + PERF_TIMER("DriverLoader::loadDriver"); // The driver-load work runs inside std::call_once so it happens exactly once // per process. Critically, we must NOT let an exception propagate *out of* the // call_once callable: on musl libc (Alpine/musllinux) libstdc++ routes @@ -1573,6 +1580,7 @@ void SqlHandle::markImplicitlyFreed() { * If you need destruction logs, use explicit close() methods instead. */ void SqlHandle::free() { + PERF_TIMER("SqlHandle::free"); if (_handle && SQLFreeHandle_ptr) { // GH-610: Clear describe cache to prevent memory leak. describeCache.clear(); @@ -1722,6 +1730,7 @@ SQLRETURN SQLResetStmt_wrap(SqlHandlePtr statementHandle) { } SQLRETURN SQLGetTypeInfo_Wrapper(SqlHandlePtr StatementHandle, SQLSMALLINT DataType) { + PERF_TIMER("SQLGetTypeInfo_Wrapper"); if (!SQLGetTypeInfo_ptr) { ThrowStdException("SQLGetTypeInfo function not loaded"); } @@ -1733,6 +1742,7 @@ SQLRETURN SQLGetTypeInfo_Wrapper(SqlHandlePtr StatementHandle, SQLSMALLINT DataT SQLRETURN SQLProcedures_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj, const py::object& schemaObj, const py::object& procedureObj) { + PERF_TIMER("SQLProcedures_wrap"); if (!SQLProcedures_ptr) { ThrowStdException("SQLProcedures function not loaded"); } @@ -1756,6 +1766,7 @@ SQLRETURN SQLForeignKeys_wrap(SqlHandlePtr StatementHandle, const py::object& pk const py::object& pkSchemaObj, const py::object& pkTableObj, const py::object& fkCatalogObj, const py::object& fkSchemaObj, const py::object& fkTableObj) { + PERF_TIMER("SQLForeignKeys_wrap"); if (!SQLForeignKeys_ptr) { ThrowStdException("SQLForeignKeys function not loaded"); } @@ -1787,6 +1798,7 @@ SQLRETURN SQLForeignKeys_wrap(SqlHandlePtr StatementHandle, const py::object& pk SQLRETURN SQLPrimaryKeys_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj, const py::object& schemaObj, const std::u16string& table) { + PERF_TIMER("SQLPrimaryKeys_wrap"); if (!SQLPrimaryKeys_ptr) { ThrowStdException("SQLPrimaryKeys function not loaded"); } @@ -1808,6 +1820,7 @@ SQLRETURN SQLPrimaryKeys_wrap(SqlHandlePtr StatementHandle, const py::object& ca SQLRETURN SQLStatistics_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj, const py::object& schemaObj, const std::u16string& table, SQLUSMALLINT unique, SQLUSMALLINT reserved) { + PERF_TIMER("SQLStatistics_wrap"); if (!SQLStatistics_ptr) { ThrowStdException("SQLStatistics function not loaded"); } @@ -1829,6 +1842,7 @@ SQLRETURN SQLStatistics_wrap(SqlHandlePtr StatementHandle, const py::object& cat SQLRETURN SQLColumns_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj, const py::object& schemaObj, const py::object& tableObj, const py::object& columnObj) { + PERF_TIMER("SQLColumns_wrap"); if (!SQLColumns_ptr) { ThrowStdException("SQLColumns function not loaded"); } @@ -1853,6 +1867,7 @@ SQLRETURN SQLColumns_wrap(SqlHandlePtr StatementHandle, const py::object& catalo // Helper function to check for driver errors ErrorInfo SQLCheckError_Wrap(SQLSMALLINT handleType, SqlHandlePtr handle, SQLRETURN retcode) { + PERF_TIMER("SQLCheckError_Wrap"); LOG("SQLCheckError: Checking ODBC errors - handleType=%d, retcode=%d", handleType, retcode); ErrorInfo errorInfo; if (retcode == SQL_INVALID_HANDLE) { @@ -1891,6 +1906,7 @@ ErrorInfo SQLCheckError_Wrap(SQLSMALLINT handleType, SqlHandlePtr handle, SQLRET } py::list SQLGetAllDiagRecords(SqlHandlePtr handle) { + PERF_TIMER("SQLGetAllDiagRecords"); LOG("SQLGetAllDiagRecords: Retrieving all diagnostic records for handle " "%p, handleType=%d", (void*)handle->get(), handle->type()); @@ -1938,6 +1954,7 @@ py::list SQLGetAllDiagRecords(SqlHandlePtr handle) { // Wrap SQLExecDirect SQLRETURN SQLExecDirect_wrap(SqlHandlePtr StatementHandle, const std::u16string& Query) { + PERF_TIMER("SQLExecDirect_wrap"); LOG("SQLExecDirect: Executing query directly - statement_handle=%p, " "query_length=%zu chars", (void*)StatementHandle->get(), Query.length()); @@ -1973,6 +1990,7 @@ SQLRETURN SQLExecDirect_wrap(SqlHandlePtr StatementHandle, const std::u16string& SQLRETURN SQLTables_wrap(SqlHandlePtr StatementHandle, const std::u16string& catalog, const std::u16string& schema, const std::u16string& table, const std::u16string& tableType) { + PERF_TIMER("SQLTables_wrap"); if (!SQLTables_ptr) { LOG("SQLTables: Function pointer not initialized, loading driver"); DriverLoader::getInstance().loadDriver(); @@ -2014,6 +2032,7 @@ SQLRETURN SQLExecute_wrap(const SqlHandlePtr statementHandle, py::list is_stmt_prepared, bool use_prepare, const py::dict& encoding_settings) { + PERF_TIMER("SQLExecute_wrap"); if (!statementHandle || !statementHandle->get()) { return SQL_INVALID_HANDLE; } @@ -2182,6 +2201,7 @@ SQLRETURN BindParameterArray(SqlHandle& handle, SQLHANDLE hStmt, const py::list& std::vector& paramInfos, size_t paramSetSize, std::vector>& paramBuffers, const std::string& charEncoding = "utf-8") { + PERF_TIMER("BindParameterArray"); LOG("BindParameterArray: Starting column-wise array binding - " "param_count=%zu, param_set_size=%zu", columnwise_params.size(), paramSetSize); @@ -2784,12 +2804,15 @@ SQLRETURN BindParameterArray(SqlHandle& handle, SQLHANDLE hStmt, const py::list& LOG("BindParameterArray: Calling SQLBindParameter - " "param_index=%d, buffer_length=%lld", paramIndex, static_cast(bufferLength)); - RETCODE rc = - SQLBindParameter_ptr(hStmt, static_cast(paramIndex + 1), - static_cast(info.inputOutputType), - static_cast(info.paramCType), - static_cast(info.paramSQLType), info.columnSize, - info.decimalDigits, dataPtr, bufferLength, strLenOrIndArray); + RETCODE rc; + { + PERF_TIMER("BindParameterArray::SQLBindParameter_call"); + rc = SQLBindParameter_ptr(hStmt, static_cast(paramIndex + 1), + static_cast(info.inputOutputType), + static_cast(info.paramCType), + static_cast(info.paramSQLType), info.columnSize, + info.decimalDigits, dataPtr, bufferLength, strLenOrIndArray); + } if (!SQL_SUCCEEDED(rc)) { LOG("BindParameterArray: SQLBindParameter failed - " "param_index=%d, SQLRETURN=%d", @@ -2813,6 +2836,7 @@ SQLRETURN SQLExecuteMany_wrap(const SqlHandlePtr statementHandle, const std::u16 const py::list& columnwise_params, std::vector& paramInfos, size_t paramSetSize, const py::dict& encodingSettings) { + PERF_TIMER("SQLExecuteMany_wrap"); LOG("SQLExecuteMany: Starting batch execution - param_count=%zu, " "param_set_size=%zu", columnwise_params.size(), paramSetSize); @@ -2976,6 +3000,7 @@ SQLRETURN SQLExecuteMany_wrap(const SqlHandlePtr statementHandle, const std::u16 // Wrap SQLNumResultCols SQLSMALLINT SQLNumResultCols_wrap(SqlHandlePtr statementHandle) { + PERF_TIMER("SQLNumResultCols_wrap"); LOG("SQLNumResultCols: Getting number of columns in result set for " "statement_handle=%p", (void*)statementHandle->get()); @@ -2993,6 +3018,7 @@ SQLSMALLINT SQLNumResultCols_wrap(SqlHandlePtr statementHandle) { // Wrap SQLDescribeCol SQLRETURN SQLDescribeCol_wrap(SqlHandlePtr StatementHandle, py::list& ColumnMetadata) { + PERF_TIMER("SQLDescribeCol_wrap"); LOG("SQLDescribeCol: Getting column descriptions for statement_handle=%p", (void*)StatementHandle->get()); if (!SQLDescribeCol_ptr) { @@ -3039,6 +3065,7 @@ SQLRETURN SQLSpecialColumns_wrap(SqlHandlePtr StatementHandle, SQLSMALLINT ident const py::object& catalogObj, const py::object& schemaObj, const std::u16string& table, SQLSMALLINT scope, SQLSMALLINT nullable) { + PERF_TIMER("SQLSpecialColumns_wrap"); if (!SQLSpecialColumns_ptr) { ThrowStdException("SQLSpecialColumns function not loaded"); } @@ -3059,6 +3086,7 @@ SQLRETURN SQLSpecialColumns_wrap(SqlHandlePtr StatementHandle, SQLSMALLINT ident // Wrap SQLFetch to retrieve rows SQLRETURN SQLFetch_wrap(SqlHandlePtr StatementHandle) { + PERF_TIMER("SQLFetch_wrap"); LOG("SQLFetch: Fetching next row for statement_handle=%p", (void*)StatementHandle->get()); if (!SQLFetch_ptr) { LOG("SQLFetch: Function pointer not initialized, loading driver"); @@ -3073,6 +3101,7 @@ SQLRETURN SQLFetch_wrap(SqlHandlePtr StatementHandle) { // Non-static so it can be called from inline functions in header py::object FetchLobColumnData(SQLHSTMT hStmt, SQLUSMALLINT colIndex, SQLSMALLINT cType, bool isWideChar, bool isBinary, const std::string& charEncoding) { + PERF_TIMER("FetchLobColumnData"); std::vector buffer; SQLRETURN ret = SQL_SUCCESS_WITH_INFO; int loopCount = 0; @@ -3254,6 +3283,7 @@ SQLRETURN SQLGetData_wrap(SqlHandlePtr StatementHandle, SQLUSMALLINT colCount, p const std::string& charEncoding = "utf-16le", const std::string& wcharEncoding = "utf-16le", int charCtype = SQL_C_WCHAR) { + PERF_TIMER("SQLGetData_wrap"); // Note: wcharEncoding parameter is reserved for future use // Currently WCHAR data always uses UTF-16LE for Windows compatibility (void)wcharEncoding; // Suppress unused parameter warning @@ -3928,6 +3958,7 @@ SQLRETURN SQLGetData_wrap(SqlHandlePtr StatementHandle, SQLUSMALLINT colCount, p SQLRETURN SQLFetchScroll_wrap(SqlHandlePtr StatementHandle, SQLSMALLINT FetchOrientation, SQLLEN FetchOffset, py::list& row_data) { + PERF_TIMER("SQLFetchScroll_wrap"); LOG("SQLFetchScroll_wrap: Fetching with scroll orientation=%d, offset=%ld", FetchOrientation, (long)FetchOffset); if (!SQLFetchScroll_ptr) { @@ -3964,6 +3995,7 @@ SQLRETURN SQLFetchScroll_wrap(SqlHandlePtr StatementHandle, SQLSMALLINT FetchOri // TODO: Move to anonymous namespace, since it is not used outside this file SQLRETURN SQLBindColums(SQLHSTMT hStmt, ColumnBuffers& buffers, py::list& columnNames, SQLUSMALLINT numCols, int fetchSize, int charCtype = SQL_C_WCHAR) { + PERF_TIMER("SQLBindColums"); SQLRETURN ret = SQL_SUCCESS; const bool useWideChar = (charCtype == SQL_C_WCHAR); // Bind columns based on their data types @@ -4130,11 +4162,13 @@ SQLRETURN FetchBatchData(SQLHSTMT hStmt, ColumnBuffers& buffers, py::list& colum const std::vector& lobColumns, const std::string& charEncoding = "utf-16le", int charCtype = SQL_C_WCHAR) { + PERF_TIMER("FetchBatchData"); LOG("FetchBatchData: Fetching data in batches"); SQLRETURN ret; { // Release the GIL during the blocking ODBC fetch py::gil_scoped_release release; + PERF_TIMER("FetchBatchData::SQLFetchScroll_call"); ret = SQLFetchScroll_ptr(hStmt, SQL_FETCH_NEXT, 0); } if (ret == SQL_NO_DATA) { @@ -4147,7 +4181,12 @@ SQLRETURN FetchBatchData(SQLHSTMT hStmt, ColumnBuffers& buffers, py::list& colum ret); return ret; } - // Pre-cache column metadata to avoid repeated dictionary lookups + // Pre-cache column metadata to avoid repeated dictionary lookups. + // The vectors below are consumed later by construct_rows, so they are + // declared at function scope; only the population work is wrapped in the + // cache_column_metadata timer's block (an earlier version put the timer at + // function scope, so it stayed active through construct_rows and made + // metadata caching look like a dominant fetch cost). struct ColumnInfo { SQLSMALLINT dataType; SQLULEN columnSize; @@ -4157,118 +4196,120 @@ SQLRETURN FetchBatchData(SQLHSTMT hStmt, ColumnBuffers& buffers, py::list& colum }; const bool useWideChar = (charCtype == SQL_C_WCHAR); std::vector columnInfos(numCols); - for (SQLUSMALLINT col = 0; col < numCols; col++) { - const auto& columnMeta = columnNames[col].cast(); - columnInfos[col].dataType = columnMeta["DataType"].cast(); - columnInfos[col].columnSize = columnMeta["ColumnSize"].cast(); - columnInfos[col].isLob = - std::find(lobColumns.begin(), lobColumns.end(), col + 1) != lobColumns.end(); - columnInfos[col].processedColumnSize = columnInfos[col].columnSize; - HandleZeroColumnSizeAtFetch(columnInfos[col].processedColumnSize); - - SQLSMALLINT dt = columnInfos[col].dataType; - bool isCharType = (dt == SQL_CHAR || dt == SQL_VARCHAR || dt == SQL_LONGVARCHAR); - - if (isCharType && useWideChar) { - // When VARCHAR is bound as SQL_C_WCHAR, buffer size is in SQLWCHAR - // units (same as NVARCHAR). +1 for null terminator. - columnInfos[col].fetchBufferSize = columnInfos[col].processedColumnSize + 1; - } else { - // On Linux/macOS, the ODBC driver returns UTF-8 for SQL_C_CHAR where - // each character can be up to 4 bytes. Must match SQLBindColums buffer. -#if defined(__APPLE__) || defined(__linux__) - if (isCharType) { - columnInfos[col].fetchBufferSize = columnInfos[col].processedColumnSize * 4 + - 1; // *4 for UTF-8, +1 for null terminator - } else { - columnInfos[col].fetchBufferSize = - columnInfos[col].processedColumnSize + 1; // +1 for null terminator - } -#else - columnInfos[col].fetchBufferSize = - columnInfos[col].processedColumnSize + 1; // +1 for null terminator -#endif - } - } - - // Performance: Build function pointer dispatch table (once per batch) + // Performance: Build function pointer dispatch table (once per batch). // This eliminates the switch statement from the hot loop - 10,000 rows × 10 - // cols reduces from 100,000 switch evaluations to just 10 switch - // evaluations + // cols reduces from 100,000 switch evaluations to just 10 switch evaluations. std::vector columnProcessors(numCols); std::vector columnInfosExt(numCols); - // Compute effective char encoding once for the batch (same for all columns) const std::string effectiveCharEnc = GetEffectiveCharDecoding(charEncoding); - for (SQLUSMALLINT col = 0; col < numCols; col++) { - // Populate extended column info for processors that need it - columnInfosExt[col].dataType = columnInfos[col].dataType; - columnInfosExt[col].columnSize = columnInfos[col].columnSize; - columnInfosExt[col].processedColumnSize = columnInfos[col].processedColumnSize; - columnInfosExt[col].fetchBufferSize = columnInfos[col].fetchBufferSize; - columnInfosExt[col].isLob = columnInfos[col].isLob; - columnInfosExt[col].charEncoding = effectiveCharEnc; - columnInfosExt[col].isUtf8 = (effectiveCharEnc == "utf-8"); - // Set useWideChar for SQL_CHAR/VARCHAR columns when charCtype is SQL_C_WCHAR - SQLSMALLINT dt = columnInfos[col].dataType; - bool isCharType = (dt == SQL_CHAR || dt == SQL_VARCHAR || dt == SQL_LONGVARCHAR); - columnInfosExt[col].useWideChar = (isCharType && useWideChar); - - // Map data type to processor function (switch executed once per column, - // not per cell) - SQLSMALLINT dataType = columnInfos[col].dataType; - switch (dataType) { - case SQL_INTEGER: - columnProcessors[col] = ColumnProcessors::ProcessInteger; - break; - case SQL_SMALLINT: - columnProcessors[col] = ColumnProcessors::ProcessSmallInt; - break; - case SQL_BIGINT: - columnProcessors[col] = ColumnProcessors::ProcessBigInt; - break; - case SQL_TINYINT: - columnProcessors[col] = ColumnProcessors::ProcessTinyInt; - break; - case SQL_BIT: - columnProcessors[col] = ColumnProcessors::ProcessBit; - break; - case SQL_REAL: - columnProcessors[col] = ColumnProcessors::ProcessReal; - break; - case SQL_DOUBLE: - case SQL_FLOAT: - columnProcessors[col] = ColumnProcessors::ProcessDouble; - break; - case SQL_CHAR: - case SQL_VARCHAR: - case SQL_LONGVARCHAR: - columnProcessors[col] = ColumnProcessors::ProcessChar; - break; - case SQL_WCHAR: - case SQL_WVARCHAR: - case SQL_WLONGVARCHAR: - columnProcessors[col] = ColumnProcessors::ProcessWChar; - break; - case SQL_SS_UDT: - case SQL_BINARY: - case SQL_VARBINARY: - case SQL_LONGVARBINARY: - columnProcessors[col] = ColumnProcessors::ProcessBinary; - break; - default: - // For complex types (Decimal, DateTime, Guid, etc.), set to - // nullptr and handle via fallback switch in the hot loop - columnProcessors[col] = nullptr; - break; + { + PERF_TIMER("FetchBatchData::cache_column_metadata"); + for (SQLUSMALLINT col = 0; col < numCols; col++) { + const auto& columnMeta = columnNames[col].cast(); + columnInfos[col].dataType = columnMeta["DataType"].cast(); + columnInfos[col].columnSize = columnMeta["ColumnSize"].cast(); + columnInfos[col].isLob = + std::find(lobColumns.begin(), lobColumns.end(), col + 1) != lobColumns.end(); + columnInfos[col].processedColumnSize = columnInfos[col].columnSize; + HandleZeroColumnSizeAtFetch(columnInfos[col].processedColumnSize); + + SQLSMALLINT dt = columnInfos[col].dataType; + bool isCharType = (dt == SQL_CHAR || dt == SQL_VARCHAR || dt == SQL_LONGVARCHAR); + + if (isCharType && useWideChar) { + // When VARCHAR is bound as SQL_C_WCHAR, buffer size is in SQLWCHAR + // units (same as NVARCHAR). +1 for null terminator. + columnInfos[col].fetchBufferSize = columnInfos[col].processedColumnSize + 1; + } else { + // On Linux/macOS, the ODBC driver returns UTF-8 for SQL_C_CHAR where + // each character can be up to 4 bytes. Must match SQLBindColums buffer. +#if defined(__APPLE__) || defined(__linux__) + if (isCharType) { + columnInfos[col].fetchBufferSize = columnInfos[col].processedColumnSize * 4 + + 1; // *4 for UTF-8, +1 for null terminator + } else { + columnInfos[col].fetchBufferSize = + columnInfos[col].processedColumnSize + 1; // +1 for null terminator + } +#else + columnInfos[col].fetchBufferSize = + columnInfos[col].processedColumnSize + 1; // +1 for null terminator +#endif + } } - } + + for (SQLUSMALLINT col = 0; col < numCols; col++) { + // Populate extended column info for processors that need it + columnInfosExt[col].dataType = columnInfos[col].dataType; + columnInfosExt[col].columnSize = columnInfos[col].columnSize; + columnInfosExt[col].processedColumnSize = columnInfos[col].processedColumnSize; + columnInfosExt[col].fetchBufferSize = columnInfos[col].fetchBufferSize; + columnInfosExt[col].isLob = columnInfos[col].isLob; + columnInfosExt[col].charEncoding = effectiveCharEnc; + columnInfosExt[col].isUtf8 = (effectiveCharEnc == "utf-8"); + // Set useWideChar for SQL_CHAR/VARCHAR columns when charCtype is SQL_C_WCHAR + SQLSMALLINT dt = columnInfos[col].dataType; + bool isCharType = (dt == SQL_CHAR || dt == SQL_VARCHAR || dt == SQL_LONGVARCHAR); + columnInfosExt[col].useWideChar = (isCharType && useWideChar); + + // Map data type to processor function (switch executed once per column, + // not per cell) + SQLSMALLINT dataType = columnInfos[col].dataType; + switch (dataType) { + case SQL_INTEGER: + columnProcessors[col] = ColumnProcessors::ProcessInteger; + break; + case SQL_SMALLINT: + columnProcessors[col] = ColumnProcessors::ProcessSmallInt; + break; + case SQL_BIGINT: + columnProcessors[col] = ColumnProcessors::ProcessBigInt; + break; + case SQL_TINYINT: + columnProcessors[col] = ColumnProcessors::ProcessTinyInt; + break; + case SQL_BIT: + columnProcessors[col] = ColumnProcessors::ProcessBit; + break; + case SQL_REAL: + columnProcessors[col] = ColumnProcessors::ProcessReal; + break; + case SQL_DOUBLE: + case SQL_FLOAT: + columnProcessors[col] = ColumnProcessors::ProcessDouble; + break; + case SQL_CHAR: + case SQL_VARCHAR: + case SQL_LONGVARCHAR: + columnProcessors[col] = ColumnProcessors::ProcessChar; + break; + case SQL_WCHAR: + case SQL_WVARCHAR: + case SQL_WLONGVARCHAR: + columnProcessors[col] = ColumnProcessors::ProcessWChar; + break; + case SQL_SS_UDT: + case SQL_BINARY: + case SQL_VARBINARY: + case SQL_LONGVARBINARY: + columnProcessors[col] = ColumnProcessors::ProcessBinary; + break; + default: + // For complex types (Decimal, DateTime, Guid, etc.), set to + // nullptr and handle via fallback switch in the hot loop + columnProcessors[col] = nullptr; + break; + } + } + } // end cache_column_metadata timer scope // Performance: Single-phase row creation pattern // Create each row, fill it completely, then append to results list // This prevents data corruption (no partially-filled rows) and simplifies // error handling + PERF_TIMER("FetchBatchData::construct_rows"); PyObject* rowsList = rows.ptr(); // RAII wrapper to ensure row cleanup on exception (CRITICAL: prevents @@ -4593,6 +4634,7 @@ SQLRETURN FetchMany_wrap(SqlHandlePtr StatementHandle, py::list& rows, int fetch const std::string& charEncoding = "utf-16le", const std::string& wcharEncoding = "utf-16le", int charCtype = SQL_C_WCHAR) { + PERF_TIMER("FetchMany_wrap"); // Issue #531: upgrade SQL_C_CHAR + utf-8 to SQL_C_WCHAR on Windows so the // driver does lossless UTF-16 conversion instead of returning ACP bytes. charCtype = EffectiveCharCtypeForFetch(charCtype, charEncoding); @@ -4802,6 +4844,7 @@ int32_t days_from_civil(int y, int m, int d) { SQLRETURN FetchArrowBatch_wrap(SqlHandlePtr StatementHandle, py::list& capsules, int arrowBatchSize, int charCtype) { + PERF_TIMER("FetchArrowBatch_wrap"); // Fetch narrow char data as SQL_C_CHAR if on Linux/macOS and configured by the user charCtype = EffectiveCharCtypeForFetch(charCtype, "utf-8"); @@ -5712,6 +5755,7 @@ SQLRETURN FetchAll_wrap(SqlHandlePtr StatementHandle, py::list& rows, const std::string& charEncoding = "utf-16le", const std::string& wcharEncoding = "utf-16le", int charCtype = SQL_C_WCHAR) { + PERF_TIMER("FetchAll_wrap"); // Issue #531: upgrade SQL_C_CHAR + utf-8 to SQL_C_WCHAR on Windows so the // driver does lossless UTF-16 conversion instead of returning ACP bytes. charCtype = EffectiveCharCtypeForFetch(charCtype, charEncoding); @@ -5858,6 +5902,7 @@ SQLRETURN FetchOne_wrap(SqlHandlePtr StatementHandle, py::list& row, const std::string& charEncoding = "utf-16le", const std::string& wcharEncoding = "utf-16le", int charCtype = SQL_C_WCHAR) { + PERF_TIMER("FetchOne_wrap"); // Issue #531: upgrade SQL_C_CHAR + utf-8 to SQL_C_WCHAR on Windows so the // driver does lossless UTF-16 conversion instead of returning ACP bytes. charCtype = EffectiveCharCtypeForFetch(charCtype, charEncoding); @@ -5892,6 +5937,7 @@ SQLRETURN FetchOne_wrap(SqlHandlePtr StatementHandle, py::list& row, // Wrap SQLMoreResults SQLRETURN SQLMoreResults_wrap(SqlHandlePtr StatementHandle) { + PERF_TIMER("SQLMoreResults_wrap"); LOG("SQLMoreResults_wrap: Check for more results"); if (!SQLMoreResults_ptr) { LOG("SQLMoreResults_wrap: Function pointer not initialized. Loading " @@ -5906,6 +5952,7 @@ SQLRETURN SQLMoreResults_wrap(SqlHandlePtr StatementHandle) { // Wrap SQLFreeHandle SQLRETURN SQLFreeHandle_wrap(SQLSMALLINT HandleType, SqlHandlePtr Handle) { + PERF_TIMER("SQLFreeHandle_wrap"); LOG("SQLFreeHandle_wrap: Free SQL handle type=%d", HandleType); // Guard against a null/None handle being passed from Python - dereferencing // Handle->get() on a null shared_ptr would segfault. @@ -5937,6 +5984,7 @@ SQLRETURN SQLFreeHandle_wrap(SQLSMALLINT HandleType, SqlHandlePtr Handle) { // Wrap SQLRowCount SQLLEN SQLRowCount_wrap(SqlHandlePtr StatementHandle) { + PERF_TIMER("SQLRowCount_wrap"); LOG("SQLRowCount_wrap: Get number of rows affected by last execute"); if (!SQLRowCount_ptr) { LOG("SQLRowCount_wrap: Function pointer not initialized. Loading the " @@ -6165,6 +6213,29 @@ PYBIND11_MODULE(ddbc_bindings, m) { return SQLColumns_wrap(StatementHandle, catalog, schema, table, column); }); + // Add profiling submodule (only in profiling builds; compiled out by default) +#ifdef ENABLE_PROFILING + auto profiling = m.def_submodule("profiling", "Performance profiling"); + profiling.def("enable", []() { mssql_profiling::PerformanceCounter::instance().enable(); }, + "Enable performance profiling"); + profiling.def("disable", []() { mssql_profiling::PerformanceCounter::instance().disable(); }, + "Disable performance profiling"); + profiling.def("get_stats", []() { return mssql_profiling::PerformanceCounter::instance().get_stats(); }, + "Get profiling statistics"); + profiling.def("get_timeline", []() { return mssql_profiling::PerformanceCounter::instance().get_timeline(); }, + "Get timeline events (list of {name, start_us, duration_us})"); + profiling.def("reset", []() { mssql_profiling::PerformanceCounter::instance().reset(); }, + "Reset profiling statistics and timeline"); + profiling.def("reset_stats_only", []() { mssql_profiling::PerformanceCounter::instance().reset_stats_only(); }, + "Reset profiling statistics but keep timeline"); + profiling.def("is_enabled", []() { return mssql_profiling::PerformanceCounter::instance().is_enabled(); }, + "Check if profiling is enabled"); + profiling.def("enable_timeline", []() { mssql_profiling::PerformanceCounter::instance().enable_timeline(); }, + "Enable timeline recording (resets epoch)"); + profiling.def("disable_timeline", []() { mssql_profiling::PerformanceCounter::instance().disable_timeline(); }, + "Disable timeline recording"); +#endif // ENABLE_PROFILING + // Add a version attribute m.attr("__version__") = "1.0.0"; diff --git a/mssql_python/pybind/performance_counter.hpp b/mssql_python/pybind/performance_counter.hpp new file mode 100644 index 00000000..3d52bd91 --- /dev/null +++ b/mssql_python/pybind/performance_counter.hpp @@ -0,0 +1,213 @@ +/* + * Performance Profiling for mssql-python + * Thread-safe performance counter with Python API + */ + +#pragma once + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +namespace py = pybind11; + +namespace mssql_profiling { + +// Platform detection +#if defined(_WIN32) || defined(_WIN64) + #define PROFILING_PLATFORM "windows" +#elif defined(__linux__) + #define PROFILING_PLATFORM "linux" +#elif defined(__APPLE__) || defined(__MACH__) + #define PROFILING_PLATFORM "macos" +#else + #define PROFILING_PLATFORM "unknown" +#endif + +struct PerfStats { + // Accumulate in NANOSECONDS. Converting each sample to whole microseconds + // before summing (as an earlier version did) truncated every sub-microsecond + // call to 0, so high-frequency timers under-reported. int64 nanoseconds holds + // ~292 years, so overflow is not a concern. get_stats() converts to us. + int64_t total_time_ns = 0; + int64_t call_count = 0; + int64_t min_time_ns = INT64_MAX; + int64_t max_time_ns = 0; +}; + +struct TimelineEvent { + std::string name; + int64_t start_us; // offset from epoch_ + int64_t duration_us; +}; + +class PerformanceCounter { +private: + std::unordered_map counters_; + std::vector timeline_; + // Intentional design decision: a single global mutex guards the counters. + // It is only taken when profiling is enabled (record() early-returns before + // the lock when disabled), so the default OFF path pays nothing. The target + // use case is single-threaded diagnostics (a user reproduces a slow query + // and sends a dump), where the lock is uncontended and negligible against + // microsecond-scale timers. Multithreaded profiling would contend this lock; + // if that ever becomes a real need, switch to thread_local accumulation + // merged at get_stats(). Not worth the added complexity today. + std::mutex mutex_; + // Config flags are atomic so enable()/disable()/enable_timeline() can be + // called from a different thread than the one running timers (timers execute + // with the GIL released). epoch_ is written under mutex_ in enable_timeline() + // and only read under mutex_ in record(), so it needs no separate atomic. + std::atomic enabled_{false}; + std::atomic timeline_enabled_{false}; + std::chrono::time_point epoch_; + +public: + static PerformanceCounter& instance() { + static PerformanceCounter counter; + return counter; + } + + void enable() { enabled_ = true; } + void disable() { enabled_ = false; } + bool is_enabled() const { return enabled_; } + + void enable_timeline() { + std::lock_guard lock(mutex_); + // Clear stale events when (re)setting the epoch so every event in + // timeline_ shares the current epoch; a second enable_timeline() without + // an intervening reset() would otherwise mix offsets from two epochs. + timeline_.clear(); + epoch_ = std::chrono::steady_clock::now(); + timeline_enabled_ = true; + } + void disable_timeline() { timeline_enabled_ = false; } + bool is_timeline_enabled() const { return timeline_enabled_; } + + void record(const std::string& name, int64_t duration_ns, + std::chrono::time_point start) { + if (!enabled_) return; + + std::lock_guard lock(mutex_); + auto& stats = counters_[name]; + stats.total_time_ns += duration_ns; + stats.call_count++; + stats.min_time_ns = std::min(stats.min_time_ns, duration_ns); + stats.max_time_ns = std::max(stats.max_time_ns, duration_ns); + + if (timeline_enabled_) { + auto offset = std::chrono::duration_cast(start - epoch_).count(); + timeline_.push_back({name, offset, duration_ns / 1000}); + } + } + + py::dict get_stats() { + std::lock_guard lock(mutex_); + py::dict result; + + for (const auto& [name, stats] : counters_) { + py::dict d; + // Convert accumulated nanoseconds to microseconds only here (never + // per-sample), keeping sub-microsecond precision as fractional us so + // high-frequency timers do not truncate to zero. + d["total_us"] = stats.total_time_ns / 1000.0; + d["calls"] = stats.call_count; + d["avg_us"] = stats.call_count > 0 + ? static_cast(stats.total_time_ns) / stats.call_count / 1000.0 + : 0.0; + d["min_us"] = stats.min_time_ns == INT64_MAX ? 0.0 : stats.min_time_ns / 1000.0; + d["max_us"] = stats.max_time_ns / 1000.0; + d["platform"] = PROFILING_PLATFORM; + result[py::str(name)] = d; + } + + return result; + } + + void reset() { + std::lock_guard lock(mutex_); + counters_.clear(); + timeline_.clear(); + } + + void reset_stats_only() { + std::lock_guard lock(mutex_); + counters_.clear(); + } + + py::list get_timeline() { + std::lock_guard lock(mutex_); + py::list result; + for (const auto& ev : timeline_) { + py::dict d; + d["name"] = ev.name; + d["start_us"] = ev.start_us; + d["duration_us"] = ev.duration_us; + result.append(d); + } + return result; + } +}; + +// RAII timer - automatically records on destruction +class ScopedTimer { +private: + const char* name_; + std::chrono::time_point start_; + // Capture the enabled state ONCE at construction. Using this captured flag + // (instead of re-checking is_enabled() in the destructor) means a concurrent + // enable()/disable() between construction and destruction can never make us + // read an uninitialized start_ or record a half-open interval. + bool active_; + +public: + explicit ScopedTimer(const char* name) + : name_(name), active_(PerformanceCounter::instance().is_enabled()) { + if (active_) { + start_ = std::chrono::steady_clock::now(); + } + } + + ~ScopedTimer() { + if (active_) { + // A destructor is implicitly noexcept: if record() threw (its + // unordered_map insert / vector push_back can throw bad_alloc), the + // exception would call std::terminate and crash the driver — but only + // while profiling. Swallow any failure so profiling can never take the + // process down; a dropped sample is an acceptable cost under OOM. + try { + auto end = std::chrono::steady_clock::now(); + auto duration_ns = + std::chrono::duration_cast(end - start_).count(); + PerformanceCounter::instance().record(name_, duration_ns, start_); + } catch (...) { + // ignore: never let a profiling timer abort the process + } + } + } +}; + +} // namespace mssql_profiling + +// Convenience macro - use __COUNTER__ for unique variable names even with nested timers +// __COUNTER__ is supported by MSVC, GCC, and Clang +#define PERF_TIMER_CONCAT_IMPL(x, y) x##y +#define PERF_TIMER_CONCAT(x, y) PERF_TIMER_CONCAT_IMPL(x, y) + +// PERF_TIMER is gated at COMPILE TIME by the ENABLE_PROFILING flag (see CMakeLists.txt). +// Release builds define nothing -> every PERF_TIMER expands to a no-op, so there is zero +// instrumentation in the shipped binary (no code, no unwind tables, no optimizer barrier). +// Profiling builds pass -DENABLE_PROFILING -> the RAII ScopedTimer is emitted. +#ifdef ENABLE_PROFILING + #define PERF_TIMER(name) mssql_profiling::ScopedTimer PERF_TIMER_CONCAT(_perf_timer_, __COUNTER__)("ddbc::" name) +#else + #define PERF_TIMER(name) do {} while(0) +#endif diff --git a/profiler/README.md b/profiler/README.md new file mode 100644 index 00000000..431bc971 --- /dev/null +++ b/profiler/README.md @@ -0,0 +1,141 @@ +# Profiler (internal) + +A performance profiler for developing the mssql-python driver. It shows where +time goes inside a database call, split across the two layers the driver is +built from: + +- the **Python layer** (`mssql_python/cursor.py` and friends), and +- the **native C++ layer** (`mssql_python/pybind/`, compiled into `ddbc_bindings`). + +A normal Python profiler (cProfile, py-spy) sees the whole C++ layer as one +opaque block. This tool instruments both layers with named timers, so you can +see, for example, that a slow query spent its time in native parameter binding +rather than in Python. + +This is a **development / internal tool** and is not meant for end users (yet). +The native (C++) instrumentation is compiled out of released wheels, so the +shipped driver's native path carries no profiler code. The Python-layer markers +(`perf_timer.py` and the `perf_phase(...)` calls in `cursor.py`) do ship, but +they are phase-level and, when profiling is disabled, reduce to a shared no-op +context manager whose end-to-end cost is within run-to-run noise. + +## How the timers are named + +Every timer has a prefix telling you which layer it belongs to: + +- `py::...` — a phase in the Python layer (e.g. `py::execute::cpp_call`) +- `ddbc::...` — a function in the native C++ layer (e.g. `ddbc::FetchAll_wrap`) + +## Step 1: build with profiling turned on + +Profiling is **off by default** and the native instrumentation is compiled out +of normal builds (no native profiler code in the shipped driver). To get a +profiling build, set one environment variable before building the C++ extension: + +```bash +# macOS / Linux +cd mssql_python/pybind +ENABLE_PROFILING=1 bash build.sh + +# Windows +cd mssql_python\pybind +set ENABLE_PROFILING=1 +build.bat +``` + +Without `ENABLE_PROFILING`, the native `ddbc_bindings.profiling` module does not +exist and the C++ timers do nothing. + +## Step 2: run the profiler + +You need a SQL Server to run against. Point `DB_CONNECTION_STRING` at it: + +```bash +export DB_CONNECTION_STRING="Server=localhost,1433;Database=master;UID=sa;Pwd=...;Encrypt=no;TrustServerCertificate=yes;" +``` + +Then either use the command-line runner, or drive it from Python. + +### Option A: command-line runner + +```bash +python -m profiler --list # show the built-in scenarios +python -m profiler --scenarios select fetchall # run specific ones +python -m profiler --script my_repro.py # run your own script (see below) +``` + +`--script` runs any Python file with a live `conn` and `cursor` already created +for you, and reports whatever timers it hits. This is how you profile a specific +slow query you are trying to diagnose: + +```python +# my_repro.py — `conn` and `cursor` are provided +cursor.execute("SELECT ... your slow query ...") +cursor.fetchall() +``` + +### Option B: from Python directly + +If you want the raw numbers without the runner, enable both layers, run your +code, then read the stats: + +```python +from mssql_python import perf_timer # Python layer +from mssql_python import ddbc_bindings # native layer (profiling build only) + +perf_timer.enable() +ddbc_bindings.profiling.enable() + +# ... run your queries ... + +py_stats = perf_timer.get_stats() # {name: {calls, total_us, min_us, max_us}} +cpp_stats = ddbc_bindings.profiling.get_stats() + +perf_timer.disable() # stop recording when done +ddbc_bindings.profiling.disable() +perf_timer.reset() # and clear the counters +ddbc_bindings.profiling.reset() +``` + +## Reading the output + +Each timer reports four numbers: + +- `calls` — how many times it ran +- `total_us` — total microseconds spent inside it +- `min_us` / `max_us` — fastest and slowest single call + +The runner merges both layers into one table sorted by total time, so the +biggest cost is at the top. A `py::` timer that wraps a `ddbc::` call (e.g. +`py::execute::cpp_call` around `ddbc::SQLExecute_wrap`) lets you see the +Python-to-C++ boundary cost as the difference between the two. + +There is also a timeline view (`--timeline`, or `get_timeline()`), which returns +each timer event in the order it happened with a start offset — useful for +seeing the sequence and nesting of a single slow operation rather than just +totals. + +## Adding a timer + +To time a new spot in the code: + +**Python** — wrap the block: + +```python +from mssql_python.perf_timer import perf_phase + +with perf_phase("py::my_area::my_step"): + ... # the code you want to measure +``` + +**C++** — add one line at the top of the scope (RAII, stops automatically): + +```cpp +void MyFunction(...) { + PERF_TIMER("MyFunction"); // becomes ddbc::MyFunction + ... +} +``` + +`PERF_TIMER` compiles to nothing unless the build has `ENABLE_PROFILING`, so +adding timers costs nothing in released builds. diff --git a/profiler/__init__.py b/profiler/__init__.py new file mode 100644 index 00000000..f41e6d38 --- /dev/null +++ b/profiler/__init__.py @@ -0,0 +1,21 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT license. +""" +mssql-python profiler — unified Python + C++ performance instrumentation. + +Usage: + python -m profiler # run all scenarios + python -m profiler --scenarios fetch insert # run specific scenarios + python -m profiler --conn-str "Server=..." # pass connection string + +Programmatic: + from profiler import Profiler + + p = Profiler(conn_str) + results = p.run("fetchall", "insertmanyvalues") # prints tables, returns results + p.close() +""" + +from profiler.core import Profiler + +__all__ = ["Profiler"] diff --git a/profiler/__main__.py b/profiler/__main__.py new file mode 100644 index 00000000..d34753eb --- /dev/null +++ b/profiler/__main__.py @@ -0,0 +1,72 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT license. +""" +CLI entry point: python -m profiler [options] +""" + +import argparse +import sys + +from profiler import Profiler +from profiler.scenarios import SCENARIOS + + +def main(): + parser = argparse.ArgumentParser( + prog="python -m profiler", + description="mssql-python performance profiler — Python + C++ instrumentation", + ) + parser.add_argument( + "--conn-str", + help="Connection string (or set DB_CONNECTION_STRING env var)", + ) + parser.add_argument( + "--scenarios", + nargs="+", + metavar="NAME", + choices=list(SCENARIOS.keys()), + help=f"Scenarios to run (default: all). Choices: {', '.join(SCENARIOS.keys())}", + ) + parser.add_argument( + "--script", + metavar="FILE", + help="Run a custom .py script. The script gets `conn` and `cursor` injected.", + ) + parser.add_argument( + "--timeline", + action="store_true", + help="Show chronological timeline instead of aggregate stats", + ) + parser.add_argument( + "--list", + action="store_true", + help="List available scenarios and exit", + ) + args = parser.parse_args() + + if args.list: + print("Available scenarios:") + for name in SCENARIOS: + print(f" {name}") + return + + try: + with Profiler(args.conn_str, timeline=args.timeline) as p: + if args.script: + p.run_script(args.script) + elif args.scenarios: + p.run(*args.scenarios) + else: + p.run() + except (ValueError, RuntimeError, FileNotFoundError) as e: + # ValueError: bad scenario name / missing conn str. + # RuntimeError: native profiling not built (rebuild with ENABLE_PROFILING). + # FileNotFoundError: --script path doesn't exist. + # Surface any of these as a clean one-line error + non-zero exit instead + # of a traceback. + print(f"Error: {e}", file=sys.stderr) + sys.exit(1) + + +if __name__ == "__main__": + main() diff --git a/profiler/core.py b/profiler/core.py new file mode 100644 index 00000000..4fdfde03 --- /dev/null +++ b/profiler/core.py @@ -0,0 +1,283 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT license. +""" +Profiler core — orchestrates scenarios, collects stats from both layers. + + from profiler import Profiler + + p = Profiler("Server=localhost,1433;UID=sa;Pwd=...;Encrypt=no;TrustServerCertificate=yes;") + p.run() # all scenarios + p.run("fetchall") # one scenario +""" + +from __future__ import annotations + +import os +import platform + +from profiler.reporter import print_stats, print_timeline +from profiler.scenarios import SCENARIOS, setup_test_data + + +class _ProfilingContext: + """Thin wrapper that enables/disables/collects from both C++ and Python profiling.""" + + def __init__(self): + from mssql_python import ddbc_bindings, perf_timer + + if not hasattr(ddbc_bindings, "profiling"): + raise RuntimeError( + "Native profiling is not available in this build. The C++ extension " + "was built without profiling instrumentation. Rebuild it with " + "ENABLE_PROFILING=1 (e.g. `ENABLE_PROFILING=1 bash " + "mssql_python/pybind/build.sh`, or `set ENABLE_PROFILING=1` then " + "`build.bat` on Windows) before running the profiler." + ) + self._cpp = ddbc_bindings.profiling + self._py = perf_timer + self._timeline_mode = False + + def set_timeline(self, on: bool): + self._timeline_mode = on + + def enable(self, timeline: bool = False): + # Start a clean measurement window. Reset first so anything that leaked + # between windows (teardown of the previous scenario, test-data setup, a + # scenario's own pre-enable cursor.execute) is discarded and only the work + # between this enable() and the matching collect() is ever counted. + # Persist the timeline decision so collect() (which preserves timeline + # events only when _timeline_mode is set) can never disagree with how + # timeline recording was turned on here. + if timeline: + self._timeline_mode = True + self._cpp.reset() + self._py.reset() + self._cpp.enable() + self._py.enable() + if self._timeline_mode: + self._cpp.enable_timeline() + self._py.enable_timeline() + + def collect(self) -> tuple[dict, dict]: + # End the measurement window: snapshot, then turn profiling OFF so nothing + # outside a window (commit/close, inter-scenario setup) gets recorded. + cpp = self._cpp.get_stats() + py = self._py.get_stats() + self._cpp.disable() + self._py.disable() + if self._timeline_mode: + # Keep timeline events for the subsequent collect_timeline(); clearing + # only aggregate counters. Recording is already gated off by disable(). + self._cpp.reset_stats_only() + self._py.reset_stats_only() + else: + self._cpp.reset() + self._py.reset() + return cpp, py + + def collect_timeline(self) -> tuple[list, list]: + cpp_tl = self._cpp.get_timeline() + py_tl = self._py.get_timeline() + self._cpp.reset() + self._py.reset() + return cpp_tl, py_tl + + def disable(self): + # Fully turn profiling off (both aggregate and timeline recording). + self._cpp.disable() + self._py.disable() + self._cpp.disable_timeline() + self._py.disable_timeline() + + def disable_timeline(self): + self._cpp.disable_timeline() + self._py.disable_timeline() + + +class Profiler: + def __init__(self, conn_str: str | None = None, timeline: bool = False): + self.conn_str = conn_str or os.getenv("DB_CONNECTION_STRING") + if not self.conn_str: + raise ValueError( + "Connection string required. Pass it directly or set DB_CONNECTION_STRING." + ) + self._ctx = _ProfilingContext() + self._timeline = timeline + self._ctx.set_timeline(timeline) + self._conn = None + self._table = None + self._results: list[dict] = [] + + def _ensure_connection(self): + if self._conn is None: + from mssql_python import connect + + self._conn = connect(self.conn_str) + self._conn.autocommit = False + + def _ensure_test_data(self): + if self._table is None: + self._ensure_connection() + print("Setting up test data...", end=" ", flush=True) + self._table = setup_test_data(self._conn) + # No drain needed: each scenario's enable() resets before measuring, + # so any stats generated by setup are discarded at the window start. + print("Done", flush=True) + + def run(self, *scenario_names: str) -> list[dict]: + names = list(scenario_names) if scenario_names else list(SCENARIOS.keys()) + unknown = set(names) - set(SCENARIOS.keys()) + if unknown: + raise ValueError(f"Unknown scenarios: {unknown}. Available: {list(SCENARIOS.keys())}") + + self._print_header() + results = [] + + for i, name in enumerate(names, 1): + fn, needs_table = SCENARIOS[name] + print(f"\n{'#' * 100}") + print(f"# {i}. {name.upper()}") + print(f"{'#' * 100}") + + # Build args based on what the scenario function needs. Wrap the call + # so a scenario that raises can never leave profiling enabled and bleed + # into the next scenario — one guard here covers all scenarios (and any + # future ones) instead of a try/finally in every scenario body. + try: + if name == "connect": + result = fn(self.conn_str, self._ctx) + elif name == "insertmanyvalues": + self._ensure_connection() + result = fn(self._conn, self._ctx) + elif name == "commit_rollback": + self._ensure_connection() + result = fn(self._conn, self._ctx) + elif needs_table: + self._ensure_test_data() + result = fn(self._conn, self._table, self._ctx) + else: + self._ensure_connection() + result = fn(self._conn, self._ctx) + finally: + self._ctx.disable() + + # Collect timeline if enabled + if self._timeline: + cpp_tl, py_tl = self._ctx.collect_timeline() + self._ctx.disable_timeline() + result["cpp_timeline"] = cpp_tl + result["py_timeline"] = py_tl + + # Print result + detail = result.get("detail", "") + if detail: + print(f"\n {detail}, Wall clock: {result['wall_ms']:.1f}ms") + else: + print(f"\n Wall clock: {result['wall_ms']:.1f}ms") + + if self._timeline: + print_timeline( + result.get("cpp_timeline"), result.get("py_timeline"), result["title"] + ) + else: + print_stats(result["cpp"], result["py"], result["title"]) + + results.append(result) + + self._results = results + self._print_footer() + return results + + def run_script(self, script_path: str) -> dict: + """Run a user-supplied .py script and report whatever timers it hits. + + The script gets `conn` (a live Connection) and `cursor` (a fresh Cursor) + injected into its namespace. + """ + import time + from pathlib import Path + + path = Path(script_path) + if not path.is_file(): + raise FileNotFoundError(f"Script not found: {script_path}") + + self._ensure_connection() + cursor = self._conn.cursor() + + self._print_header() + print(f"\n{'#' * 100}") + print(f"# CUSTOM: {path.name}") + print(f"{'#' * 100}") + + ns = { + "conn": self._conn, + "cursor": cursor, + "__name__": "__main__", + "__file__": str(path), + } + + try: + # compile() is inside the guard so a SyntaxError in the user script + # still closes the cursor via the finally below. + code = compile(path.read_text(), str(path), "exec") + self._ctx.enable(timeline=self._timeline) + # Start the wall-clock only after enable(), so file read and compile + # (which the profiling counters don't see) aren't charged to the script. + t0 = time.perf_counter() + exec(code, ns) # noqa: S102 + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = self._ctx.collect() + if self._timeline: + cpp_tl, py_tl = self._ctx.collect_timeline() + self._ctx.disable_timeline() + finally: + # Always end the window and close the cursor, even if compile()/exec() + # raised, so profiling state and the cursor never leak into a later run. + self._ctx.disable() + cursor.close() + + result = { + "title": f"CUSTOM: {path.name}", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + } + + if self._timeline: + result["cpp_timeline"] = cpp_tl + result["py_timeline"] = py_tl + + print(f"\n Wall clock: {wall_ms:.1f}ms") + if self._timeline: + print_timeline(result.get("cpp_timeline"), result.get("py_timeline"), result["title"]) + else: + print_stats(cpp, py, result["title"]) + self._print_footer() + return result + + def close(self): + # Always turn profiling off so a programmatic caller doesn't leave the + # process-wide counters enabled after using the Profiler. + self._ctx.disable() + if self._conn: + self._conn.close() + self._conn = None + self._table = None + + def _print_header(self): + print("=" * 100) + print("mssql-python profiler") + print("=" * 100) + print(f"Platform: {platform.system()} {platform.release()} ({platform.machine()})") + print(f"Python: {platform.python_version()}") + + def _print_footer(self): + print(f"\n{'=' * 100}") + print("PROFILING COMPLETE") + print("=" * 100) + + def __enter__(self): + return self + + def __exit__(self, *_): + self.close() diff --git a/profiler/reporter.py b/profiler/reporter.py new file mode 100644 index 00000000..d962718e --- /dev/null +++ b/profiler/reporter.py @@ -0,0 +1,89 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT license. +"""Stats collection and reporting — merges Python (py::) and C++ timer data.""" + +from __future__ import annotations + + +def merge_stats(cpp_stats: dict | None, py_stats: dict | None) -> dict: + merged = {} + for name, s in (cpp_stats or {}).items(): + merged[name] = s + for name, s in (py_stats or {}).items(): + merged[name] = s + return merged + + +def merge_timeline(cpp_timeline: list | None, py_timeline: list | None) -> list[dict]: + events = list(cpp_timeline or []) + list(py_timeline or []) + events.sort(key=lambda e: e["start_us"]) + return events + + +def format_stats_table(stats: dict, title: str) -> str: + if not stats: + return f"\n{title}: No data collected" + + lines = [ + "", + "=" * 100, + title, + "=" * 100, + f" {'Function':<55} {'Calls':>8} {'Total(ms)':>12} " + f"{'Avg(us)':>12} {'Min(us)':>10} {'Max(us)':>10}", + f" {'-' * 107}", + ] + for name, s in sorted(stats.items(), key=lambda x: x[1]["total_us"], reverse=True): + total_ms = s["total_us"] / 1000.0 + avg_us = s["total_us"] / s["calls"] if s["calls"] > 0 else 0 + min_us = 0 if s["min_us"] > 1e15 else s["min_us"] + lines.append( + f" {name:<55} {s['calls']:>8} {total_ms:>12.3f} " + f"{avg_us:>12.1f} {min_us:>10.1f} {s['max_us']:>10.1f}" + ) + return "\n".join(lines) + + +def format_timeline(events: list[dict], title: str) -> str: + if not events: + return f"\n{title}: No timeline events" + + lines = [ + "", + "=" * 110, + f"TIMELINE: {title}", + "=" * 110, + f" {'Start(ms)':>10} {'Dur(ms)':>10} {'End(ms)':>10} {'Function'}", + f" {'-' * 104}", + ] + + # Build a simple nesting stack based on time overlap + stack: list[tuple[int, int]] = [] # (start_us, end_us) of active spans + for ev in events: + s = ev["start_us"] + d = ev["duration_us"] + e = s + d + + # Pop spans that don't fully contain this event + while stack and stack[-1][1] < e: + stack.pop() + + depth = len(stack) + indent = " " * depth + start_ms = s / 1000.0 + dur_ms = d / 1000.0 + end_ms = e / 1000.0 + + lines.append(f" {start_ms:>10.3f} {dur_ms:>10.3f} {end_ms:>10.3f} {indent}{ev['name']}") + + stack.append((s, e)) + + return "\n".join(lines) + + +def print_stats(cpp_stats: dict | None, py_stats: dict | None, title: str): + print(format_stats_table(merge_stats(cpp_stats, py_stats), title)) + + +def print_timeline(cpp_timeline: list | None, py_timeline: list | None, title: str): + print(format_timeline(merge_timeline(cpp_timeline, py_timeline), title)) diff --git a/profiler/scenarios.py b/profiler/scenarios.py new file mode 100644 index 00000000..15d5c12c --- /dev/null +++ b/profiler/scenarios.py @@ -0,0 +1,351 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT license. +""" +Profiling scenarios — each is a self-contained benchmark that yields +a (title, wall_ms, cpp_stats, py_stats) result. + +Scenarios generate their own test data and clean up after themselves. +Only requires a connection string and a live SQL Server instance. +""" + +from __future__ import annotations + +import time +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from mssql_python.connection import Connection + +# --------------------------------------------------------------------------- +# Defaults +# --------------------------------------------------------------------------- +ROW_COUNT = 50_000 +EXECUTEMANY_ROWS = 5_000 +FETCHMANY_SIZE = 1_000 +FETCHONE_ROWS = 1_000 +INSERT_COUNT = 100 +COMMIT_ROLLBACK_COUNT = 100 +IMV_ROWS_PER_BATCH = 1_000 # 2000 params, under 2100 limit +IMV_TOTAL_ROWS = 100_000 + +_TEST_TABLE = "#perf_test" + +_CREATE_TABLE = f""" +IF OBJECT_ID('tempdb..{_TEST_TABLE}', 'U') IS NOT NULL DROP TABLE {_TEST_TABLE}; +CREATE TABLE {_TEST_TABLE} ( + id INT IDENTITY(1,1) PRIMARY KEY, + int_col INT, bigint_col BIGINT, float_col FLOAT, + varchar_col VARCHAR(100), nvarchar_col NVARCHAR(100), + date_col DATE, datetime_col DATETIME2, + decimal_col DECIMAL(18,4), bit_col BIT +); +""" + +_INSERT_COLS = ( + "int_col, bigint_col, float_col, varchar_col, nvarchar_col, " + "date_col, datetime_col, decimal_col, bit_col" +) +_INSERT_PLACEHOLDERS = "?, ?, ?, ?, ?, ?, ?, ?, ?" + + +def _make_rows(n: int) -> list[tuple]: + return [ + ( + i, + i * 1_000_000, + i * 1.5, + f"row_{i}_data", + f"unicode_row_{i}", + "2024-06-15", + "2024-06-15 14:30:00.123456", + f"{i}.1234", + i % 2, + ) + for i in range(n) + ] + + +def setup_test_data(conn: "Connection", row_count: int = ROW_COUNT) -> str: + cursor = conn.cursor() + cursor.execute(_CREATE_TABLE) + conn.commit() + cursor.executemany( + f"INSERT INTO {_TEST_TABLE} ({_INSERT_COLS}) VALUES ({_INSERT_PLACEHOLDERS})", + _make_rows(row_count), + ) + conn.commit() + cursor.close() + return _TEST_TABLE + + +# --------------------------------------------------------------------------- +# Individual scenarios +# --------------------------------------------------------------------------- + + +def connect(conn_str: str, ctx) -> dict: + from mssql_python import connect as _connect + + ctx.enable() + t0 = time.perf_counter() + c = _connect(conn_str) + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + c.close() + return {"title": "CONNECT", "wall_ms": wall_ms, "cpp": cpp, "py": py} + + +def execute_select(conn, table, ctx) -> dict: + cursor = conn.cursor() + ctx.enable() + t0 = time.perf_counter() + cursor.execute(f"SELECT * FROM {table} WHERE id <= 100") + rows = cursor.fetchall() + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + cursor.close() + return { + "title": f"EXECUTE SELECT ({len(rows)} rows)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"Rows: {len(rows)}", + } + + +def execute_insert(conn, table, ctx, count: int = INSERT_COUNT) -> dict: + cursor = conn.cursor() + ctx.enable() + t0 = time.perf_counter() + for i in range(count): + cursor.execute( + f"INSERT INTO {table} ({_INSERT_COLS}) VALUES ({_INSERT_PLACEHOLDERS})", + ( + i, + i * 1000, + 1.5, + f"insert_{i}", + f"ins_{i}", + "2025-01-01", + "2025-01-01 12:00:00", + "99.99", + 1, + ), + ) + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + # Roll back so these rows don't persist in the shared table and inflate the + # row counts of later fetch scenarios. The insert work is already measured. + conn.rollback() + cursor.close() + return { + "title": f"EXECUTE INSERT ({count}x)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"{count} individual INSERTs", + } + + +def executemany(conn, table, ctx, row_count: int = EXECUTEMANY_ROWS) -> dict: + cursor = conn.cursor() + params = [ + (i, i * 1000, 1.5, f"batch_{i}", f"b_{i}", "2025-01-01", "2025-01-01 12:00:00", "99.99", 1) + for i in range(row_count) + ] + ctx.enable() + t0 = time.perf_counter() + cursor.executemany( + f"INSERT INTO {table} ({_INSERT_COLS}) VALUES ({_INSERT_PLACEHOLDERS})", + params, + ) + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + # Roll back so these rows don't persist in the shared table and inflate the + # row counts of later fetch scenarios. The insert work is already measured. + conn.rollback() + cursor.close() + return { + "title": f"EXECUTEMANY ({row_count} rows)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"{row_count} rows via executemany", + } + + +def fetchall(conn, table, ctx) -> dict: + cursor = conn.cursor() + cursor.execute(f"SELECT * FROM {table}") + ctx.enable() + t0 = time.perf_counter() + rows = cursor.fetchall() + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + cursor.close() + return { + "title": f"FETCHALL ({len(rows)} rows)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"Rows: {len(rows)}", + } + + +def fetchone(conn, table, ctx, row_count: int = FETCHONE_ROWS) -> dict: + cursor = conn.cursor() + cursor.execute(f"SELECT TOP {row_count} * FROM {table}") + ctx.enable() + t0 = time.perf_counter() + count = 0 + while True: + row = cursor.fetchone() + if row is None: + break + count += 1 + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + cursor.close() + return { + "title": f"FETCHONE ({count} rows)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"Rows: {count}", + } + + +def fetchmany(conn, table, ctx, batch_size: int = FETCHMANY_SIZE) -> dict: + cursor = conn.cursor() + cursor.execute(f"SELECT * FROM {table}") + ctx.enable() + t0 = time.perf_counter() + total = 0 + while True: + batch = cursor.fetchmany(batch_size) + if not batch: + break + total += len(batch) + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + cursor.close() + return { + "title": f"FETCHMANY ({total} rows, batch={batch_size})", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"Rows: {total}, Batch size: {batch_size}", + } + + +def commit_rollback(conn, ctx, count: int = COMMIT_ROLLBACK_COUNT) -> dict: + conn.autocommit = False + cursor = conn.cursor() + ctx.enable() + t0 = time.perf_counter() + for _ in range(count): + cursor.execute("SELECT 1") + conn.commit() + for _ in range(count): + cursor.execute("SELECT 1") + conn.rollback() + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + cursor.close() + return { + "title": f"COMMIT/ROLLBACK ({count} each)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"{count} commits + {count} rollbacks", + } + + +def fetch_arrow(conn, table, ctx) -> dict: + cursor = conn.cursor() + cursor.execute(f"SELECT * FROM {table}") + ctx.enable() + t0 = time.perf_counter() + try: + batch = cursor.arrow_batch(batch_size=ROW_COUNT) + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + row_count = batch.num_rows if batch else 0 + cursor.close() + return { + "title": f"FETCH ARROW ({row_count} rows)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"Arrow rows: {row_count}", + } + except ImportError as e: + # Only pyarrow-not-installed is an expected "skip"; let any real driver + # error propagate so a genuine Arrow regression can't be silently reported + # as a zero-time success. + ctx.disable() + cursor.close() + return { + "title": "FETCH ARROW", + "wall_ms": 0, + "cpp": None, + "py": None, + "detail": f"Skipped (pyarrow not available): {e}", + } + + +def insertmanyvalues( + conn, ctx, rows_per_batch: int = IMV_ROWS_PER_BATCH, total_rows: int = IMV_TOTAL_ROWS +) -> dict: + """SQLAlchemy insertmanyvalues pattern: batched multi-row INSERT via cursor.execute().""" + num_batches = total_rows // rows_per_batch + params_per_call = rows_per_batch * 2 + + cursor = conn.cursor() + cursor.execute( + "IF OBJECT_ID('tempdb..#imv_bench', 'U') IS NOT NULL DROP TABLE #imv_bench;" + "CREATE TABLE #imv_bench (id INT, name VARCHAR(50))" + ) + conn.commit() + + sql = "INSERT INTO #imv_bench (id, name) VALUES " + ",".join(["(?, ?)"] * rows_per_batch) + params = [] + for i in range(rows_per_batch): + params.extend([i, f"user_{i:06d}"]) + + ctx.enable() + t0 = time.perf_counter() + for _ in range(num_batches): + cursor.execute(sql, params) + conn.commit() + wall_ms = (time.perf_counter() - t0) * 1000 + cpp, py = ctx.collect() + actual = num_batches * rows_per_batch + rps = actual / (wall_ms / 1000) if wall_ms > 0 else 0 + cursor.close() + return { + "title": f"INSERTMANYVALUES ({actual:,} rows, {params_per_call} params/call)", + "wall_ms": wall_ms, + "cpp": cpp, + "py": py, + "detail": f"{actual:,} rows via {num_batches} execute() calls ({rps:,.0f} rows/s)", + } + + +# --------------------------------------------------------------------------- +# Registry +# --------------------------------------------------------------------------- + +# Maps scenario name -> (function, needs_table) +SCENARIOS: dict[str, tuple] = { + "connect": (connect, False), + "select": (execute_select, True), + "insert": (execute_insert, True), + "executemany": (executemany, True), + "fetchall": (fetchall, True), + "fetchone": (fetchone, True), + "fetchmany": (fetchmany, True), + "commit_rollback": (commit_rollback, False), + "arrow": (fetch_arrow, True), + "insertmanyvalues": (insertmanyvalues, False), +} diff --git a/setup.py b/setup.py index 921521ff..c3e17cb9 100644 --- a/setup.py +++ b/setup.py @@ -160,12 +160,19 @@ def run(self): # --------------------------------------------------------------------------- # Find all packages in the current directory. +# Exclude profiler/: it's internal development tooling (a standalone benchmark +# CLI), not part of the shipped driver, and its generic top-level name should +# not land in users' site-packages. The runtime instrumentation it drives lives +# inside mssql_python (perf_timer.py, the ddbc_bindings profiling submodule) and +# is packaged normally. # Exclude mssql_python_odbc: it is shipped exclusively by the standalone # mssql-python-odbc distribution (see setup_odbc.py) and pulled in via # install_requires. Shipping it here too would make two distributions own the # same import directory (install-order file overwrites; uninstall of one can # remove files the other needs). -packages = find_packages(exclude=["mssql_python_odbc", "mssql_python_odbc.*"]) +packages = find_packages( + exclude=["profiler", "profiler.*", "mssql_python_odbc", "mssql_python_odbc.*"] +) # Get platform info using consolidated function arch, platform_tag = get_platform_info() diff --git a/tests/test_025_profiler.py b/tests/test_025_profiler.py new file mode 100644 index 00000000..bd582de5 --- /dev/null +++ b/tests/test_025_profiler.py @@ -0,0 +1,444 @@ +""" +Tests for the internal performance profiler. + +Two layers are exercised: +- Python layer: mssql_python.perf_timer (perf_phase / perf_start / perf_stop, + enable/disable, stats, timeline). +- C++ layer: the mssql_python.ddbc_bindings.profiling submodule backed by + performance_counter.hpp. + +The profiler is internal development tooling and is a no-op unless enabled. +Every test here resets and disables both layers on teardown so profiling state +never leaks into the rest of the suite. +""" + +import os +import time + +import pytest + +from mssql_python import perf_timer + +try: + import mssql_python.ddbc_bindings as ddbc + + CPP_PROFILING = hasattr(ddbc, "profiling") +except ImportError: + ddbc = None + CPP_PROFILING = False + + +@pytest.fixture(autouse=True) +def _clean_profiling_state(): + """Guarantee profiling is off and empty before and after each test.""" + perf_timer.disable() + perf_timer.disable_timeline() + perf_timer.reset() + if CPP_PROFILING: + ddbc.profiling.disable() + ddbc.profiling.disable_timeline() + ddbc.profiling.reset() + yield + perf_timer.disable() + perf_timer.disable_timeline() + perf_timer.reset() + if CPP_PROFILING: + ddbc.profiling.disable() + ddbc.profiling.disable_timeline() + ddbc.profiling.reset() + + +# --------------------------------------------------------------------------- +# Python layer: mssql_python.perf_timer +# --------------------------------------------------------------------------- + + +def test_disabled_by_default_and_toggle(): + assert perf_timer.is_enabled() is False + perf_timer.enable() + assert perf_timer.is_enabled() is True + perf_timer.disable() + assert perf_timer.is_enabled() is False + + +def test_perf_phase_is_noop_when_disabled(): + with perf_timer.perf_phase("py::test::noop"): + pass + assert perf_timer.get_stats() == {} + + +def test_perf_phase_records_when_enabled(): + perf_timer.enable() + with perf_timer.perf_phase("py::test::phase"): + time.sleep(0.002) + stats = perf_timer.get_stats() + assert "py::test::phase" in stats + entry = stats["py::test::phase"] + assert set(entry.keys()) == {"calls", "total_us", "min_us", "max_us"} + assert entry["calls"] == 1 + assert entry["total_us"] > 0 + assert entry["min_us"] <= entry["max_us"] + + +def test_perf_phase_aggregates_multiple_calls(): + perf_timer.enable() + for _ in range(3): + with perf_timer.perf_phase("py::test::loop"): + time.sleep(0.001) + entry = perf_timer.get_stats()["py::test::loop"] + assert entry["calls"] == 3 + + +def test_submicrosecond_samples_accumulate_without_truncation(): + """Regression: each sample is accumulated in nanoseconds and converted to us + only at get_stats(). Five 300 ns samples must sum to 1.5 us, not truncate to + zero the way per-sample us rounding did.""" + perf_timer.enable() + perf_timer.reset() + for _ in range(5): + perf_timer._record("py::test::subus", 300) # 300 ns, well under 1 us + entry = perf_timer.get_stats()["py::test::subus"] + assert entry["calls"] == 5 + assert entry["total_us"] == 1.5 # 5 * 300 ns = 1500 ns = 1.5 us + assert entry["min_us"] == 0.3 # a single sub-us sample survives as fractional us + assert entry["max_us"] == 0.3 + + +def test_perf_start_stop_pairs(): + perf_timer.enable() + t0 = perf_timer.perf_start() + assert t0 > 0 + time.sleep(0.001) + perf_timer.perf_stop("py::test::manual", t0) + assert perf_timer.get_stats()["py::test::manual"]["calls"] == 1 + + +def test_perf_start_stop_noop_when_disabled(): + t0 = perf_timer.perf_start() + assert t0 == 0 + perf_timer.perf_stop("py::test::manual_disabled", t0) + assert perf_timer.get_stats() == {} + + +def test_reset_stats_only_keeps_timeline(): + perf_timer.enable() + perf_timer.enable_timeline() + with perf_timer.perf_phase("py::test::keep_timeline"): + time.sleep(0.001) + assert perf_timer.get_stats() != {} + assert perf_timer.get_timeline() != [] + perf_timer.reset_stats_only() + assert perf_timer.get_stats() == {} + # timeline survives reset_stats_only + assert perf_timer.get_timeline() != [] + + +def test_reset_clears_everything(): + perf_timer.enable() + perf_timer.enable_timeline() + with perf_timer.perf_phase("py::test::clear_all"): + time.sleep(0.001) + perf_timer.reset() + assert perf_timer.get_stats() == {} + assert perf_timer.get_timeline() == [] + + +def test_timeline_event_shape(): + perf_timer.enable() + perf_timer.enable_timeline() + with perf_timer.perf_phase("py::test::timeline"): + time.sleep(0.001) + timeline = perf_timer.get_timeline() + assert len(timeline) == 1 + ev = timeline[0] + assert set(ev.keys()) == {"name", "start_us", "duration_us"} + assert ev["name"] == "py::test::timeline" + assert ev["duration_us"] >= 0 + + +def test_timeline_not_recorded_when_timeline_disabled(): + perf_timer.enable() + # timeline explicitly disabled + with perf_timer.perf_phase("py::test::no_timeline"): + time.sleep(0.001) + assert perf_timer.get_stats() != {} + assert perf_timer.get_timeline() == [] + + +# --------------------------------------------------------------------------- +# C++ layer: ddbc_bindings.profiling submodule +# --------------------------------------------------------------------------- + +_CONN_STR = os.getenv("DB_CONNECTION_STRING") +_needs_cpp = pytest.mark.skipif( + not CPP_PROFILING, reason="ddbc_bindings.profiling submodule not available" +) +_needs_db = pytest.mark.skipif(not _CONN_STR, reason="DB_CONNECTION_STRING not set") + + +@_needs_cpp +def test_cpp_profiling_toggle(): + assert ddbc.profiling.is_enabled() is False + ddbc.profiling.enable() + assert ddbc.profiling.is_enabled() is True + ddbc.profiling.disable() + assert ddbc.profiling.is_enabled() is False + + +@_needs_cpp +def test_cpp_get_stats_empty_when_reset(): + ddbc.profiling.reset() + assert ddbc.profiling.get_stats() == {} + assert ddbc.profiling.get_timeline() == [] + + +@_needs_cpp +@_needs_db +def test_cpp_profiling_captures_query(): + import mssql_python + + ddbc.profiling.enable() + conn = mssql_python.connect(_CONN_STR) + try: + cur = conn.cursor() + cur.execute("SELECT 1") + cur.fetchall() + cur.close() + finally: + conn.close() + + stats = ddbc.profiling.get_stats() + assert len(stats) > 0 + # every C++ timer name carries the ddbc:: prefix + assert all(name.startswith("ddbc::") for name in stats) + sample = next(iter(stats.values())) + assert {"calls", "total_us", "min_us", "max_us", "avg_us", "platform"}.issubset(sample.keys()) + assert sample["calls"] >= 1 + + +@_needs_cpp +@_needs_db +def test_cpp_timeline_captures_events(): + import mssql_python + + ddbc.profiling.enable() + ddbc.profiling.enable_timeline() + conn = mssql_python.connect(_CONN_STR) + try: + cur = conn.cursor() + cur.execute("SELECT 1") + cur.fetchall() + cur.close() + finally: + conn.close() + + timeline = ddbc.profiling.get_timeline() + assert len(timeline) > 0 + ev = timeline[0] + assert set(ev.keys()) == {"name", "start_us", "duration_us"} + + +@_needs_cpp +@_needs_db +def test_cpp_reset_stats_only_keeps_timeline(): + import mssql_python + + ddbc.profiling.enable() + ddbc.profiling.enable_timeline() + conn = mssql_python.connect(_CONN_STR) + try: + cur = conn.cursor() + cur.execute("SELECT 1") + cur.fetchall() + cur.close() + finally: + conn.close() + + assert ddbc.profiling.get_stats() != {} + assert ddbc.profiling.get_timeline() != [] + ddbc.profiling.reset_stats_only() + assert ddbc.profiling.get_stats() == {} + assert ddbc.profiling.get_timeline() != [] + + +# --------------------------------------------------------------------------- +# Profiler measurement-window isolation (profiler/core.py _ProfilingContext) +# --------------------------------------------------------------------------- + + +@_needs_cpp +def test_context_collect_disables_profiling(): + """collect() must end the window: after it, profiling is off in both layers.""" + from profiler.core import _ProfilingContext + + ctx = _ProfilingContext() + ctx.enable() + assert perf_timer.is_enabled() is True + assert ddbc.profiling.is_enabled() is True + with perf_timer.perf_phase("py::window::work"): + pass + cpp, py = ctx.collect() + # window recorded its work... + assert "py::window::work" in py + # ...and profiling is now OFF so nothing after this point is counted. + assert perf_timer.is_enabled() is False + assert ddbc.profiling.is_enabled() is False + + +@_needs_cpp +def test_context_enable_timeline_arg_survives_collect(): + """Turning timeline on via enable(timeline=True) — without set_timeline() — + must still make collect() preserve timeline events for collect_timeline(). + Regression: collect() used to consult only _timeline_mode, so an enable-arg + request was silently dropped and the events were cleared.""" + from profiler.core import _ProfilingContext + + ctx = _ProfilingContext() + ctx.enable(timeline=True) # request timeline via the arg, not set_timeline() + with perf_timer.perf_phase("py::tl::work"): + pass + ctx.collect() # must keep timeline events (reset_stats_only, not reset) + _, py_tl = ctx.collect_timeline() + assert any( + ev["name"] == "py::tl::work" for ev in py_tl + ), f"timeline events were cleared on collect(): {py_tl}" + + +@_needs_cpp +def test_context_windows_do_not_leak_into_each_other(): + """Work done between two windows must not appear in the next window's stats.""" + from profiler.core import _ProfilingContext + + ctx = _ProfilingContext() + + # Window 1: does real work. + ctx.enable() + with perf_timer.perf_phase("py::w1::work"): + pass + ctx.collect() + + # Between windows (profiling is off now): this must NOT be recorded. + with perf_timer.perf_phase("py::between::leak"): + pass + + # Window 2: enable() resets, and we collect immediately with no work. + ctx.enable() + cpp2, py2 = ctx.collect() + assert py2 == {}, f"window 2 leaked stats from between windows: {py2}" + assert "py::between::leak" not in py2 + + +@_needs_cpp +def test_context_disable_turns_everything_off(): + from profiler.core import _ProfilingContext + + ctx = _ProfilingContext() + ctx.enable(timeline=True) + ctx.disable() + assert perf_timer.is_enabled() is False + assert ddbc.profiling.is_enabled() is False + + +@_needs_cpp +@_needs_db +def test_run_script_disables_profiling_even_when_script_raises(tmp_path): + """A user script that raises must not leave profiling enabled.""" + from profiler.core import Profiler + + bad = tmp_path / "boom.py" + bad.write_text("cursor.execute('SELECT 1')\nraise RuntimeError('boom')\n") + + p = Profiler(_CONN_STR) + try: + with pytest.raises(RuntimeError): + p.run_script(str(bad)) + # window must be closed despite the exception + assert perf_timer.is_enabled() is False + assert ddbc.profiling.is_enabled() is False + finally: + p.close() + + +def test_enable_timeline_clears_stale_events(): + """A second enable_timeline() must not leave events from the previous epoch.""" + perf_timer.enable() + perf_timer.enable_timeline() + with perf_timer.perf_phase("py::epoch1::evt"): + pass + assert len(perf_timer.get_timeline()) == 1 + # Re-arm timeline without an explicit reset(): stale events must be dropped + # so all remaining events share the new epoch. + perf_timer.enable_timeline() + assert perf_timer.get_timeline() == [] + with perf_timer.perf_phase("py::epoch2::evt"): + pass + tl = perf_timer.get_timeline() + assert len(tl) == 1 + assert tl[0]["name"] == "py::epoch2::evt" + + +def test_perf_phase_records_even_when_body_raises(): + """__exit__ must record the sample even if the wrapped block raises, so the + Python call counts don't silently desync from the C++ ones.""" + perf_timer.enable() + with pytest.raises(ValueError): + with perf_timer.perf_phase("py::raises::evt"): + raise ValueError("boom") + stats = perf_timer.get_stats() + assert "py::raises::evt" in stats + assert stats["py::raises::evt"]["calls"] == 1 + + +def test_perf_phase_disabled_returns_shared_noop(): + """Disabled perf_phase returns the shared singleton (no per-call allocation).""" + assert perf_timer.is_enabled() is False + a = perf_timer.perf_phase("py::x") + b = perf_timer.perf_phase("py::y") + assert a is b # same shared _NULL_PHASE instance + with a: + pass + assert perf_timer.get_stats() == {} + + +@_needs_cpp +@_needs_db +def test_run_script_bad_syntax_still_cleans_up(tmp_path): + """A script that fails to COMPILE must still disable profiling (and not leak).""" + from profiler.core import Profiler + + bad = tmp_path / "syntax.py" + bad.write_text("this is not valid python !!!\n") + + p = Profiler(_CONN_STR) + try: + with pytest.raises(SyntaxError): + p.run_script(str(bad)) + assert perf_timer.is_enabled() is False + assert ddbc.profiling.is_enabled() is False + finally: + p.close() + + +@_needs_cpp +@_needs_db +def test_run_script_wall_time_reflects_exec_not_io(tmp_path): + """wall_ms should track the script's execution (a known sleep), which only + holds because the timer starts after read+compile. If read/compile were + inside the window the assertion would still pass, so we also bound it from + above to catch gross inflation.""" + from profiler.core import Profiler + + # Script sleeps a known amount; that sleep must show up in wall_ms. + script = tmp_path / "sleeper.py" + script.write_text("import time\ntime.sleep(0.20)\n") + + p = Profiler(_CONN_STR) + try: + result = p.run_script(str(script)) + # Lower bound: the 200 ms sleep must be measured (window covers exec). + assert result["wall_ms"] >= 180 + # Upper bound: not grossly inflated beyond the sleep (a few hundred ms + # of slack for interpreter overhead, never seconds of I/O). + assert result["wall_ms"] < 1000 + finally: + p.close()