Skip to content

FEAT: Profiler - #552

Open
Gaurav Sharma (bewithgaurav) wants to merge 26 commits into
mainfrom
bewithgaurav/profiling
Open

FEAT: Profiler#552
Gaurav Sharma (bewithgaurav) wants to merge 26 commits into
mainfrom
bewithgaurav/profiling

Conversation

@bewithgaurav

@bewithgaurav Gaurav Sharma (bewithgaurav) commented Apr 30, 2026

Copy link
Copy Markdown
Collaborator

Work Item / Issue Reference

ADO Work Item: Fixed AB#44819


Summary

Adds a performance profiler for diagnosing where time goes inside a database call, split across the two layers the driver is built from: the Python layer (cursor.py) and the native C++ layer (ddbc_bindings). A normal Python profiler sees the entire native layer as one opaque block; this instruments both layers with named timers so a slow call can be attributed to, for example, native parameter binding rather than Python.

This is an internal development tool. The C++ instrumentation is compiled out of released wheels (see below), so the native driver carries no profiler code. The Python-side phase markers are lightweight and remain in the shipped cursor.py; when profiling is disabled they are a no-op branch whose measured end-to-end cost is within run-to-run noise versus a no-profiler build.

How it is built in

  • The C++ instrumentation is gated at compile time by an ENABLE_PROFILING CMake option, off by default. Normal builds expand every PERF_TIMER to a no-op and do not register the native ddbc_bindings.profiling submodule, so there is no native profiler code, no unwind tables, and no runtime branch in the released binary. Internal/dev builds opt in with ENABLE_PROFILING=1 bash build.sh (or set ENABLE_PROFILING=1 + build.bat on Windows).
  • The Python instrumentation (perf_timer.py and the perf_phase(...) markers in cursor.py) cannot be compiled out the same way, so it ships. When profiling is disabled, perf_phase returns a shared no-op context manager (measured at ~110 ns per marker in isolation). Some markers do sit on per-row paths (e.g. three in the fetchone loop), but that per-marker cost is orders of magnitude below per-row DB latency, so measured end-to-end overhead on execute/fetch workloads stays within run-to-run noise versus a no-profiler build.

What it adds (in profiling builds only)

  • C++ layer: performance_counter.hpp provides a PERF_TIMER("name") RAII macro and instruments ddbc_bindings.cpp and the connection sources, exposed to Python as the ddbc_bindings.profiling submodule.
  • Python layer: perf_timer.py provides perf_phase("name") context managers around the execute/fetch phases in cursor.py. The ddbc:: and py:: prefixes identify which layer a timer belongs to.
  • Runner: the profiler/ CLI (python -m profiler) with built-in scenarios plus aggregate and timeline reports, and a --script flag for profiling an arbitrary workload. profiler/ is dev-only and excluded from the shipped wheel.

Concurrency

The native counter uses a single global mutex, taken only when profiling is enabled. The target is single-threaded diagnostics where the lock is uncontended; this is a deliberate simplification documented in performance_counter.hpp.

Tests

tests/test_025_profiler.py covers both layers (Python perf_timer and, when built with profiling, the ddbc_bindings.profiling submodule). The C++ cases skip automatically on a non-profiling build.

Follow-up work (intentionally out of scope for this PR)

This PR ships the internal profiler tooling only. The following are deliberately deferred to follow-up PRs and are not oversights:

  • CI does not build the profiling configuration. No pipeline currently sets ENABLE_PROFILING, so the profiling build and its native-layer tests are not exercised in CI. A follow-up will add an ENABLE_PROFILING build/test leg (Linux + Windows). This is tied to the planned work to drive CI benchmarks from profiler data, where these builds and the scenario set become the fixed workloads a regression gate runs.
  • End-user profiling experience. A minimal enable/dump API and a separate profiling wheel (so a customer can install one artifact, reproduce, and send a dump) are left for a follow-up designed with the team.

Everything gated behind ENABLE_PROFILING (off by default) means neither deferral affects released wheels today.

Tasks 1, 2, 3: Update profiler, add new profiling points, expand benchmarks

Phase 1: Core Infrastructure (COMPLETE)
- Add performance_counter.hpp with thread-safe RAII profiling
- Integrate profiling submodule into ddbc_bindings.cpp
- Port run_profiler.py and profiling_results.md from old branch
- Support for enable/disable/get_stats/reset via Python API

Phase 2: Documentation (COMPLETE)
- PROFILER_SUMMARY.md: Executive summary and quick reference
- PERF_TIMER_LOCATIONS.md: All 43 timer locations with code snippets
- ENHANCED_PROFILING_PLAN.md: New profiling points and benchmarks
- PROFILER_UPGRADE_STATUS.md: Status tracker and phases

Phase 3: Implementation (TODO)
- 43 PERF_TIMER calls need to be added (documented in detail)
- New profiling points for types, transactions, pool, memory
- Comprehensive benchmark suite (8 new categories)

Key Features:
- Platform detection (Windows/Linux/macOS)
- Per-function timing with min/max/avg
- Granular timers for construct_rows bottleneck
- Designed for Windows vs Linux performance analysis

Reference PR: #147 (original profiler branch)
Based on analysis showing 2.3x Linux slowdown (now 16% after optimizations)
- perf_timer.py: Python phase-level profiling (perf_phase, perf_start/perf_stop)
- performance_counter.hpp: C++ timeline recording, ddbc:: prefix via macro
- cursor.py: Phase timers on execute, fetch*, executemany
- ddbc_bindings.cpp, connection.cpp, connection_pool.cpp: PERF_TIMER calls
- profiler/: CLI package (python -m profiler) with scenarios, timeline mode,
  custom script support (--script), aggregate + waterfall reporters
- my_bench.py: Example custom profiling script
@bewithgaurav Gaurav Sharma (bewithgaurav) changed the title Bewithgaurav/profiling FEAT: Profiler May 7, 2026
Re-apply py:: and ddbc:: profiling instrumentation on top of main's u16string signature migration, GIL-release changes, and the issue #531 charCtype fetch path. No behavior change to profiling; timers preserved across the refactored execute/fetch/connect paths.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Drop the root-level planning/status notes (ENHANCED_PROFILING_PLAN, LATEST_UPDATE, PERF_TIMER_LOCATIONS, PROFILER_SUMMARY, PROFILER_UPGRADE_STATUS, profiling_results) and my_bench.py. These were working scratch from building the profiler and shouldn't ship. The profiler tooling itself (profiler/, mssql_python/perf_timer.py, performance_counter.hpp) stays.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
The merge resolution accidentally scoped main's 'skip detect_and_convert_parameters when re-executing the same SQL' fast path to only the multi-arg branch. Main applies it to both the single-container (execute(sql, (a, b))) and multi-arg forms. Restore main's structure: compute actual_params in the if/else, then run the same-SQL shortcut once for both, still inside the py::execute::param_unpack timer.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Comment thread mssql_python/cursor.py Dismissed
Comment thread profiler/core.py Dismissed
@github-actions

github-actions Bot commented Jul 6, 2026

Copy link
Copy Markdown

📊 Code Coverage Report

🔥 Diff Coverage

67%


🎯 Overall Coverage

82%


📈 Total Lines Covered: 8115 out of 9779
📁 Project: mssql-python


Diff Coverage

Diff: main...HEAD, staged and unstaged changes

  • mssql_python/cursor.py (97.0%): Missing lines 2894,2896
  • mssql_python/perf_timer.py (98.6%): Missing lines 172
  • mssql_python/pybind/connection/connection.cpp (73.3%): Missing lines 216,232,248,287
  • mssql_python/pybind/connection/connection_pool.cpp (100%)
  • mssql_python/pybind/ddbc_bindings.cpp (82.5%): Missing lines 863-865,871-872,1733,2807,3003,4171,4201,4207-4209,4218-4220,4245,4263-4265,4270,4304-4306
  • mssql_python/pybind/performance_counter.hpp (1.0%): Missing lines 74-77,79-81,83-93,96-110,112-133,135-139,141-144,146-157,173-177,179-195

Summary

  • Total: 393 lines
  • Missing: 129 lines
  • Coverage: 67%

mssql_python/cursor.py

Lines 2890-2900

  2890                         column_map_lower=column_map_lower,
  2891                     )
  2892                     for row_data in rows_data
  2893                 ]
! 2894         except Exception:
  2895             # On error, don't increment rownumber - rethrow the error
! 2896             raise
  2897 
  2898     def fetchall(self) -> List[Row]:
  2899         """
  2900         Fetch all (remaining) rows of a query result.

mssql_python/perf_timer.py

Lines 168-176

  168         entry["total_ns"] += elapsed
  169         if elapsed < entry["min_ns"]:
  170             entry["min_ns"] = elapsed
  171         if elapsed > entry["max_ns"]:
! 172             entry["max_ns"] = elapsed
  173 
  174     if _timeline_enabled and start_ns:
  175         _timeline.append(
  176             {

mssql_python/pybind/connection/connection.cpp

Lines 212-220

  212     }
  213 }
  214 
  215 void Connection::commit() {
! 216     PERF_TIMER("Connection::commit");
  217     if (!_dbcHandle) {
  218         ThrowStdException("Connection handle not allocated");
  219     }
  220     updateLastUsed();

Lines 228-236

  228     checkError(ret);
  229 }
  230 
  231 void Connection::rollback() {
! 232     PERF_TIMER("Connection::rollback");
  233     if (!_dbcHandle) {
  234         ThrowStdException("Connection handle not allocated");
  235     }
  236     updateLastUsed();

Lines 244-252

  244     checkError(ret);
  245 }
  246 
  247 void Connection::setAutocommit(bool enable) {
! 248     PERF_TIMER("Connection::setAutocommit");
  249     if (!_dbcHandle) {
  250         ThrowStdException("Connection handle not allocated");
  251     }
  252     SQLINTEGER value = enable ? SQL_AUTOCOMMIT_ON : SQL_AUTOCOMMIT_OFF;

Lines 283-291

  283     return value == SQL_AUTOCOMMIT_ON;
  284 }
  285 
  286 SqlHandlePtr Connection::allocStatementHandle() {
! 287     PERF_TIMER("Connection::allocStatementHandle");
  288     if (!_dbcHandle) {
  289         ThrowStdException("Connection handle not allocated");
  290     }
  291     updateLastUsed();

mssql_python/pybind/ddbc_bindings.cpp

Lines 859-869

  859                 ThrowStdException(errorString.str());
  860             }
  861         }
  862         assert(SQLBindParameter_ptr && SQLGetStmtAttr_ptr && SQLSetDescField_ptr);
! 863         RETCODE rc;
! 864         {
! 865             PERF_TIMER("BindParameters::SQLBindParameter_call");
  866             rc = SQLBindParameter_ptr(
  867                 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */
  868                 static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
  869                 static_cast<SQLSMALLINT>(paramInfo.paramCType),

Lines 867-876

  867                 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */
  868                 static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
  869                 static_cast<SQLSMALLINT>(paramInfo.paramCType),
  870                 static_cast<SQLSMALLINT>(paramInfo.paramSQLType), paramInfo.columnSize,
! 871                 paramInfo.decimalDigits, dataPtr, bufferLength, strLenOrIndPtr);
! 872         }
  873         if (!SQL_SUCCEEDED(rc)) {
  874             LOG("BindParameters: SQLBindParameter failed for param[%d] - "
  875                 "SQLRETURN=%d, C_Type=%d, SQL_Type=%d",
  876                 paramIndex, rc, paramInfo.paramCType, paramInfo.paramSQLType);

Lines 1729-1737

  1729     return rc;
  1730 }
  1731 
  1732 SQLRETURN SQLGetTypeInfo_Wrapper(SqlHandlePtr StatementHandle, SQLSMALLINT DataType) {
! 1733     PERF_TIMER("SQLGetTypeInfo_Wrapper");
  1734     if (!SQLGetTypeInfo_ptr) {
  1735         ThrowStdException("SQLGetTypeInfo function not loaded");
  1736     }

Lines 2803-2811

  2803             }
  2804             LOG("BindParameterArray: Calling SQLBindParameter - "
  2805                 "param_index=%d, buffer_length=%lld",
  2806                 paramIndex, static_cast<long long>(bufferLength));
! 2807             RETCODE rc;
  2808             {
  2809                 PERF_TIMER("BindParameterArray::SQLBindParameter_call");
  2810                 rc = SQLBindParameter_ptr(hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1),
  2811                                          static_cast<SQLUSMALLINT>(info.inputOutputType),

Lines 2999-3007

  2999 }
  3000 
  3001 // Wrap SQLNumResultCols
  3002 SQLSMALLINT SQLNumResultCols_wrap(SqlHandlePtr statementHandle) {
! 3003     PERF_TIMER("SQLNumResultCols_wrap");
  3004     LOG("SQLNumResultCols: Getting number of columns in result set for "
  3005         "statement_handle=%p",
  3006         (void*)statementHandle->get());
  3007     if (!SQLNumResultCols_ptr) {

Lines 4167-4175

  4167     SQLRETURN ret;
  4168     {
  4169         // Release the GIL during the blocking ODBC fetch
  4170         py::gil_scoped_release release;
! 4171         PERF_TIMER("FetchBatchData::SQLFetchScroll_call");
  4172         ret = SQLFetchScroll_ptr(hStmt, SQL_FETCH_NEXT, 0);
  4173     }
  4174     if (ret == SQL_NO_DATA) {
  4175         LOG("FetchBatchData: No data to fetch");

Lines 4197-4205

  4197     const bool useWideChar = (charCtype == SQL_C_WCHAR);
  4198     std::vector<ColumnInfo> columnInfos(numCols);
  4199     // Performance: Build function pointer dispatch table (once per batch).
  4200     // This eliminates the switch statement from the hot loop - 10,000 rows × 10
! 4201     // cols reduces from 100,000 switch evaluations to just 10 switch evaluations.
  4202     std::vector<ColumnProcessor> columnProcessors(numCols);
  4203     std::vector<ColumnInfoExt> columnInfosExt(numCols);
  4204     // Compute effective char encoding once for the batch (same for all columns)
  4205     const std::string effectiveCharEnc = GetEffectiveCharDecoding(charEncoding);

Lines 4203-4213

  4203     std::vector<ColumnInfoExt> columnInfosExt(numCols);
  4204     // Compute effective char encoding once for the batch (same for all columns)
  4205     const std::string effectiveCharEnc = GetEffectiveCharDecoding(charEncoding);
  4206 
! 4207     {
! 4208         PERF_TIMER("FetchBatchData::cache_column_metadata");
! 4209         for (SQLUSMALLINT col = 0; col < numCols; col++) {
  4210             const auto& columnMeta = columnNames[col].cast<py::dict>();
  4211             columnInfos[col].dataType = columnMeta["DataType"].cast<SQLSMALLINT>();
  4212             columnInfos[col].columnSize = columnMeta["ColumnSize"].cast<SQLULEN>();
  4213             columnInfos[col].isLob =

Lines 4214-4224

  4214                 std::find(lobColumns.begin(), lobColumns.end(), col + 1) != lobColumns.end();
  4215             columnInfos[col].processedColumnSize = columnInfos[col].columnSize;
  4216             HandleZeroColumnSizeAtFetch(columnInfos[col].processedColumnSize);
  4217 
! 4218             SQLSMALLINT dt = columnInfos[col].dataType;
! 4219             bool isCharType = (dt == SQL_CHAR || dt == SQL_VARCHAR || dt == SQL_LONGVARCHAR);
! 4220 
  4221             if (isCharType && useWideChar) {
  4222                 // When VARCHAR is bound as SQL_C_WCHAR, buffer size is in SQLWCHAR
  4223                 // units (same as NVARCHAR). +1 for null terminator.
  4224                 columnInfos[col].fetchBufferSize = columnInfos[col].processedColumnSize + 1;

Lines 4241-4249

  4241         }
  4242 
  4243         for (SQLUSMALLINT col = 0; col < numCols; col++) {
  4244             // Populate extended column info for processors that need it
! 4245             columnInfosExt[col].dataType = columnInfos[col].dataType;
  4246             columnInfosExt[col].columnSize = columnInfos[col].columnSize;
  4247             columnInfosExt[col].processedColumnSize = columnInfos[col].processedColumnSize;
  4248             columnInfosExt[col].fetchBufferSize = columnInfos[col].fetchBufferSize;
  4249             columnInfosExt[col].isLob = columnInfos[col].isLob;

Lines 4259-4274

  4259             SQLSMALLINT dataType = columnInfos[col].dataType;
  4260             switch (dataType) {
  4261                 case SQL_INTEGER:
  4262                     columnProcessors[col] = ColumnProcessors::ProcessInteger;
! 4263                     break;
! 4264                 case SQL_SMALLINT:
! 4265                     columnProcessors[col] = ColumnProcessors::ProcessSmallInt;
  4266                     break;
  4267                 case SQL_BIGINT:
  4268                     columnProcessors[col] = ColumnProcessors::ProcessBigInt;
  4269                     break;
! 4270                 case SQL_TINYINT:
  4271                     columnProcessors[col] = ColumnProcessors::ProcessTinyInt;
  4272                     break;
  4273                 case SQL_BIT:
  4274                     columnProcessors[col] = ColumnProcessors::ProcessBit;

Lines 4300-4310

  4300                     // For complex types (Decimal, DateTime, Guid, etc.), set to
  4301                     // nullptr and handle via fallback switch in the hot loop
  4302                     columnProcessors[col] = nullptr;
  4303                     break;
! 4304             }
! 4305         }
! 4306     }  // end cache_column_metadata timer scope
  4307 
  4308     // Performance: Single-phase row creation pattern
  4309     // Create each row, fill it completely, then append to results list
  4310     // This prevents data corruption (no partially-filled rows) and simplifies

mssql_python/pybind/performance_counter.hpp

Lines 70-161

   70     std::atomic<bool> timeline_enabled_{false};
   71     std::chrono::time_point<std::chrono::steady_clock> epoch_;
   72 
   73 public:
!  74     static PerformanceCounter& instance() {
!  75         static PerformanceCounter counter;
!  76         return counter;
!  77     }
   78 
!  79     void enable() { enabled_ = true; }
!  80     void disable() { enabled_ = false; }
!  81     bool is_enabled() const { return enabled_; }
   82 
!  83     void enable_timeline() {
!  84         std::lock_guard<std::mutex> lock(mutex_);
!  85         // Clear stale events when (re)setting the epoch so every event in
!  86         // timeline_ shares the current epoch; a second enable_timeline() without
!  87         // an intervening reset() would otherwise mix offsets from two epochs.
!  88         timeline_.clear();
!  89         epoch_ = std::chrono::steady_clock::now();
!  90         timeline_enabled_ = true;
!  91     }
!  92     void disable_timeline() { timeline_enabled_ = false; }
!  93     bool is_timeline_enabled() const { return timeline_enabled_; }
   94 
   95     void record(const std::string& name, int64_t duration_ns,
!  96                 std::chrono::time_point<std::chrono::steady_clock> start) {
!  97         if (!enabled_) return;
!  98 
!  99         std::lock_guard<std::mutex> lock(mutex_);
! 100         auto& stats = counters_[name];
! 101         stats.total_time_ns += duration_ns;
! 102         stats.call_count++;
! 103         stats.min_time_ns = std::min(stats.min_time_ns, duration_ns);
! 104         stats.max_time_ns = std::max(stats.max_time_ns, duration_ns);
! 105 
! 106         if (timeline_enabled_) {
! 107             auto offset = std::chrono::duration_cast<std::chrono::microseconds>(start - epoch_).count();
! 108             timeline_.push_back({name, offset, duration_ns / 1000});
! 109         }
! 110     }
  111 
! 112     py::dict get_stats() {
! 113         std::lock_guard<std::mutex> lock(mutex_);
! 114         py::dict result;
! 115 
! 116         for (const auto& [name, stats] : counters_) {
! 117             py::dict d;
! 118             // Convert accumulated nanoseconds to microseconds only here (never
! 119             // per-sample), keeping sub-microsecond precision as fractional us so
! 120             // high-frequency timers do not truncate to zero.
! 121             d["total_us"] = stats.total_time_ns / 1000.0;
! 122             d["calls"] = stats.call_count;
! 123             d["avg_us"] = stats.call_count > 0
! 124                               ? static_cast<double>(stats.total_time_ns) / stats.call_count / 1000.0
! 125                               : 0.0;
! 126             d["min_us"] = stats.min_time_ns == INT64_MAX ? 0.0 : stats.min_time_ns / 1000.0;
! 127             d["max_us"] = stats.max_time_ns / 1000.0;
! 128             d["platform"] = PROFILING_PLATFORM;
! 129             result[py::str(name)] = d;
! 130         }
! 131 
! 132         return result;
! 133     }
  134 
! 135     void reset() {
! 136         std::lock_guard<std::mutex> lock(mutex_);
! 137         counters_.clear();
! 138         timeline_.clear();
! 139     }
  140 
! 141     void reset_stats_only() {
! 142         std::lock_guard<std::mutex> lock(mutex_);
! 143         counters_.clear();
! 144     }
  145 
! 146     py::list get_timeline() {
! 147         std::lock_guard<std::mutex> lock(mutex_);
! 148         py::list result;
! 149         for (const auto& ev : timeline_) {
! 150             py::dict d;
! 151             d["name"] = ev.name;
! 152             d["start_us"] = ev.start_us;
! 153             d["duration_us"] = ev.duration_us;
! 154             result.append(d);
! 155         }
! 156         return result;
! 157     }
  158 };
  159 
  160 // RAII timer - automatically records on destruction
  161 class ScopedTimer {

Lines 169-199

  169     bool active_;
  170 
  171 public:
  172     explicit ScopedTimer(const char* name)
! 173         : name_(name), active_(PerformanceCounter::instance().is_enabled()) {
! 174         if (active_) {
! 175             start_ = std::chrono::steady_clock::now();
! 176         }
! 177     }
  178 
! 179     ~ScopedTimer() {
! 180         if (active_) {
! 181             // A destructor is implicitly noexcept: if record() threw (its
! 182             // unordered_map insert / vector push_back can throw bad_alloc), the
! 183             // exception would call std::terminate and crash the driver — but only
! 184             // while profiling. Swallow any failure so profiling can never take the
! 185             // process down; a dropped sample is an acceptable cost under OOM.
! 186             try {
! 187                 auto end = std::chrono::steady_clock::now();
! 188                 auto duration_ns =
! 189                     std::chrono::duration_cast<std::chrono::nanoseconds>(end - start_).count();
! 190                 PerformanceCounter::instance().record(name_, duration_ns, start_);
! 191             } catch (...) {
! 192                 // ignore: never let a profiling timer abort the process
! 193             }
! 194         }
! 195     }
  196 };
  197 
  198 } // namespace mssql_profiling


📋 Files Needing Attention

📉 Files with overall lowest coverage (click to expand)
mssql_python.pybind.logger_bridge.cpp: 57.9%
mssql_python.pybind.ddbc_bindings.h: 61.5%
mssql_python.pybind.logger_bridge.hpp: 70.8%
mssql_python.row.py: 77.6%
mssql_python.pybind.ddbc_bindings.cpp: 77.7%
mssql_python.pybind.connection.connection_pool.cpp: 81.8%
mssql_python.logging.py: 85.5%
mssql_python.helpers.py: 89.3%
mssql_python.pooling.py: 90.1%
mssql_python.pybind.py_type_cache.hpp: 91.6%

🔗 Quick Links

⚙️ Build Summary 📋 Coverage Details

View Azure DevOps Build

Browse Full Coverage Report

Pick up 1.11.0 release, context-manager transaction (#639), bulkcopy timeout (#650), py-core 0.1.6, and macOS dylib config (#661). No profiler conflicts; auto-merge clean.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
@github-actions github-actions Bot added the pr-size: large Substantial code update label Jul 14, 2026
find_packages() was picking up the top-level profiler/ package, so the internal benchmark CLI (and a generic 'profiler' top-level name) would ship to PyPI. Exclude it. The runtime instrumentation it drives (perf_timer.py, the ddbc_bindings profiling submodule) lives inside mssql_python and still ships.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Cover both layers: the python perf_timer (perf_phase/perf_start/perf_stop, enable/disable, stats, timeline, reset vs reset_stats_only) and the C++ ddbc_bindings.profiling submodule (toggle, live query capture, timeline, reset). Autouse fixture resets and disables both layers around every test so profiling state never leaks into the rest of the suite.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Note in performance_counter.hpp that the global mutex is taken only when profiling is enabled, targets single-threaded diagnostics where it is uncontended, and is a deliberate simplification (thread_local is the upgrade path if multithreaded profiling ever matters).

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Profiling is now compiled out of normal builds. PERF_TIMER expands to a no-op and the ddbc_bindings.profiling submodule is not registered unless the C++ extension is built with -DENABLE_PROFILING (set ENABLE_PROFILING=1 for build.sh/build.bat). Released wheels therefore ship with zero profiler code. This replaces the old manual comment-toggle in performance_counter.hpp with a real CMake option. Internal/dev builds opt in to get the instrumentation.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Explains what the two-layer profiler is, the py:: / ddbc:: prefixes, how to make a profiling build (ENABLE_PROFILING), how to run it (CLI --script or the runtime API), how to read the output, and how to add a timer. Drops the stale scenario-specific and internal references.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Re-apply py:: and ddbc:: profiling instrumentation on top of main's C++ execute-pipeline rewrite (SQLExecute_wrap single-pipeline, no ParamInfo across the pybind boundary; param detection moved to C++), the #671 GIL/env-handle and disconnect changes, identity-aware pool keying (pool_key/token_factory), the musl call_once safety in loadDriver, and the new mssql_python_odbc packaging split (combined the setup.py find_packages excludes).

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI lite review requested due to automatic review settings September 8, 2026 04:54

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Changes recommended

The new C++ profiling counter has confirmed undefined-behavior hazards (data races and an uninitialized timer start) that should be fixed before merging.

Once you've addressed the issues Copilot identified, you can request another Copilot review.

Pull request overview

This PR introduces an internal, opt-in two-layer performance profiler for diagnosing latency across the Python DB-API layer and the native ddbc_bindings C++ layer, with a dev-only profiler/ runner and a new test suite covering both layers.

Changes:

  • Adds a Python profiling module (mssql_python/perf_timer.py) and instruments key phases in Cursor.execute()/executemany()/fetch*().
  • Adds a C++ RAII timing macro (PERF_TIMER) + global counter/timeline, and exposes it as mssql_python.ddbc_bindings.profiling in profiling-enabled builds.
  • Adds a dev-only profiler/ CLI + scenarios/reporting, and excludes it from the shipped wheel via setup.py.
File summaries
File Description
tests/test_025_profiler.py Adds tests for Python and (optional) C++ profiling enable/disable, stats, and timeline.
setup.py Excludes profiler/ from distribution packages while keeping runtime instrumentation shipped.
profiler/init.py Exposes Profiler API for the internal runner package.
profiler/main.py Implements python -m profiler CLI entrypoint and argument parsing.
profiler/core.py Orchestrates scenarios and collects/prints combined C++ + Python profiling output.
profiler/reporter.py Merges and formats stats/timeline from both layers for reporting.
profiler/scenarios.py Defines benchmark scenarios and test-data setup helpers.
profiler/README.md Documents how to build/run the profiler and interpret its output.
mssql_python/pybind/performance_counter.hpp Adds C++ profiling counter/timeline and PERF_TIMER macro implementation.
mssql_python/pybind/ddbc_bindings.cpp Adds C++ timers in key ODBC paths and exposes ddbc_bindings.profiling submodule in profiling builds.
mssql_python/pybind/connection/connection.cpp Adds C++ timers around connection lifecycle and transactional operations.
mssql_python/pybind/connection/connection_pool.cpp Adds C++ timers around pool acquire/release/close and pool-manager acquire.
mssql_python/pybind/CMakeLists.txt Adds ENABLE_PROFILING CMake option and defines ENABLE_PROFILING compile definition when enabled.
mssql_python/pybind/build.sh Passes -DENABLE_PROFILING=ON to CMake when ENABLE_PROFILING env var is set.
mssql_python/pybind/build.bat Passes -DENABLE_PROFILING=ON to CMake when ENABLE_PROFILING env var is set.
mssql_python/perf_timer.py Introduces Python-layer timing (stats + optional timeline) aligned with C++ schema.
mssql_python/cursor.py Instruments execute/fetch paths with Python timers and adds a measured param-type-detection section in executemany.
Review details

Suppressed comments (3)

mssql_python/pybind/performance_counter.hpp:59

  • enabled_ and timeline_enabled_ are read/written from multiple threads (timer scopes can run concurrently with enable/disable from Python) but are plain bools accessed without synchronization; this is a C++ data race (undefined behavior). Use std::atomic (or guard all reads/writes with the mutex) to make enable checks thread-safe.
    std::mutex mutex_;
    bool enabled_ = false;
    bool timeline_enabled_ = false;
    std::chrono::time_point<std::chrono::high_resolution_clock> epoch_;

mssql_python/pybind/performance_counter.hpp:75

  • enable_timeline() writes epoch_ without holding mutex_, but record() reads epoch_ while holding mutex_. Because the write is not synchronized with the read, this is also a data race; protect epoch_ updates with the same mutex (and ideally set epoch_ before flipping timeline_enabled_ on).
    void enable_timeline() {
        timeline_enabled_ = true;
        epoch_ = std::chrono::high_resolution_clock::now();
    }
    void disable_timeline() { timeline_enabled_ = false; }

mssql_python/pybind/performance_counter.hpp:149

  • ScopedTimer only initializes start_ when profiling is enabled at construction time, but the destructor checks is_enabled() again. If profiling is toggled on between construction and destruction, start_ is uninitialized and the duration calculation becomes undefined behavior. Capture an active_ flag at construction and use it in the destructor.
    explicit ScopedTimer(const char* name) : name_(name) {
        if (PerformanceCounter::instance().is_enabled()) {
            start_ = std::chrono::high_resolution_clock::now();
        }
    }
  • Files reviewed: 17/17 changed files
  • Comments generated: 2
  • Review effort level: Lite

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread mssql_python/perf_timer.py
Comment thread mssql_python/pybind/performance_counter.hpp
Two thread-safety fixes in performance_counter.hpp, both only affecting profiling builds. (1) enabled_/timeline_enabled_ are now std::atomic and enable_timeline() writes epoch_ under the mutex, so enable/disable/enable_timeline are safe to call from a thread other than the one running timers (timers run with the GIL released). (2) ScopedTimer captures the enabled state once at construction into active_ and uses it in the destructor, instead of re-checking is_enabled(); this removes the window where profiling flipping on between ctor and dtor could read an uninitialized start_ or record a half-open interval.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 05:26

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

It contains a few correctness issues (missing standard includes in the new C++ header and missing cleanup on exceptions in Profiler.run_script()) that can break builds or leak resources.

Review details

Suppressed comments (4)

Previously missed (3) — in code that hasn't changed since the last review.

mssql_python/pybind/performance_counter.hpp:16

  • PerformanceCounter uses int64_t, INT64_MAX, and std::min/std::max but the header doesn’t include the standard headers that define them (<cstdint> / <stdint.h> and <algorithm>). This can cause build failures depending on transitive includes.
    profiler/core.py:199
  • Profiler.run_script() leaks the cursor (and leaves profiling enabled) if the user script fails to compile or raises during exec(), because cleanup only happens on the success path. Wrap execution in try/finally so cursor.close() and self._ctx.collect() always run.
    profiler/init.py:17
  • The module docstring shows p.report(), but Profiler doesn’t define a report method (and there’s no def report(...) anywhere under profiler/). This example will fail if copied.

mssql_python/perf_timer.py:108

  • perf_start() returns 0 when profiling is disabled, but perf_stop() will record a bogus duration if profiling gets enabled between start and stop (it will compute now - 0). Guarding against a zero start avoids corrupting stats in that edge case.
def perf_start() -> int:
    if not _enabled:
        return 0
    return time.perf_counter_ns()


def perf_stop(name: str, t0: int):
    if not _enabled:
        return
    _record(name, time.perf_counter_ns() - t0, t0)

  • Files reviewed: 17/17 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

…ate each other

The profiler CLI recorded across window boundaries: collect() snapshotted and reset the counters but left profiling enabled, so a scenario's teardown (commit/close), the next scenario's setup, and a fetch scenario's pre-enable cursor.execute all kept recording and bled into the next scenario's numbers. Profiler.close() also left profiling on for programmatic callers.

Make the window airtight in _ProfilingContext: enable() resets both layers before turning on (clean start, discards anything leaked between windows), collect() disables both layers after snapshotting (nothing outside a window is counted), and close() disables. Removed the now-redundant setup drain in _ensure_test_data. Added tests asserting collect() disables profiling and that work between two windows never appears in the next window's stats.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 05:31

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Changes recommended

There are correctness/robustness issues in the new profiling implementation (missing required C++ includes and cleanup gaps in the profiler runner/scenarios) that can cause build failures or leaked profiling state.

Once you've addressed the issues Copilot identified, you can request another Copilot review.

Review details

Suppressed comments (1)

mssql_python/pybind/performance_counter.hpp:15

  • performance_counter.hpp uses std::min/std::max, int64_t, and INT64_MAX but does not include the standard headers that define them. This can fail to compile depending on transitive includes. Add the missing headers explicitly (e.g., and ).
#include <chrono>
#include <string>
#include <vector>
#include <unordered_map>
#include <mutex>
#include <atomic>
#include <pybind11/pybind11.h>
#include <pybind11/stl.h>
  • Files reviewed: 17/17 changed files
  • Comments generated: 2
  • Review effort level: Lite

Comment thread profiler/core.py Outdated
Comment thread profiler/scenarios.py
…tion-safe profiler runner

performance_counter.hpp: add the standard headers it actually uses (<algorithm>, <cstdint>, <limits>) instead of relying on transitive pybind/STL includes, which is not guaranteed across toolchains. perf_timer.perf_stop: ignore a falsy (t0==0) start so a perf_start() that ran while disabled cannot record a bogus now-minus-zero duration. profiler runner: guarantee profiling is disabled even when a scenario or a --script user script raises — one try/finally in run() covers every scenario (and future ones) rather than a guard in each scenario body, and run_script() closes its cursor and ends the window in a finally. Added a test asserting a raising script leaves profiling off.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 06:32

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

Profiler.run_script() can leak a cursor if compile() raises because compilation happens outside the cleanup guard.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

profiler/core.py:214

  • run_script() compiles the user script outside the try/finally that guarantees cleanup. If compile() raises (e.g., SyntaxError), the cursor created earlier will never be closed. Wrap compile() so the cursor is closed before re-raising.
  • Files reviewed: 18/18 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

…mpile

compile() ran after the cursor was created but before the try/finally, so a SyntaxError in the user script leaked the cursor. Moved compile() (and enable()) inside the guard so the finally always closes the cursor and disables profiling. Added a test for a script with invalid syntax.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 06:39

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

executemany() uses perf_start()/perf_stop() without an exception-safe guard, which can silently drop a profiling phase on error and reduce profiler correctness.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

mssql_python/cursor.py:2483

  • executemany() uses perf_start() / perf_stop() around the parameter-type-detection loop, but perf_stop() is not in a finally (and the loop itself can raise). That means the profiler can silently drop this phase when an exception occurs, which undermines the intended invariant that phase timers still record even when the wrapped work raises (as perf_phase() does). Consider switching this section to with perf_phase("py::executemany::param_type_detection"): or wrapping the loop in try/finally so perf_stop() always runs.
  • Files reviewed: 18/18 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

…ny conversion

run_script now starts its wall clock after enable(), so file read and compile aren't charged to the script's reported time. The arrow scenario catches only ImportError (pyarrow missing) and lets any real driver error propagate, instead of a broad except that reported genuine failures as a zero-time 'Skipped'. Added a py::executemany::param_conversion timer around the per-cell time/decimal conversion loop, which previously ran outside any timer and hid the real hotspot (measured ~29ms vs ~1.5ms for the transpose it sits next to). Tests added for script wall-time and existing arrow/executemany paths.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 06:57

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

It touches hot-path cursor execution/fetch logic and adds broad native-extension instrumentation/build gating that benefits from final human validation across platforms and build modes.

Review details

Suppressed comments (3)

Previously missed (3) — in code that hasn't changed since the last review.

mssql_python/cursor.py:1735

  • The profiling phase name py::execute::param_unpack now also includes parameter-style detection and conversion (detect_and_convert_parameters), so the timer label no longer reflects what is actually being measured and can mislead profiler output. Consider renaming this phase to match the broader work being timed (or splitting it into separate phases).
    mssql_python/cursor.py:1829
  • The exception variable e is not used in this DDBCSQLDescribeCol failure handler. Keeping it creates an unused local (and can trigger lint warnings) without adding value.
    mssql_python/pybind/ddbc_bindings.cpp:3998
  • The new timer label SQLBindColums contains a typo (“Colums” vs “Columns”). Since this string shows up directly in profiler output, it's worth fixing the spelling even if the underlying helper function name is unchanged.
  • Files reviewed: 18/18 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

Two measurement-accuracy bugs surfaced in review of the native counter:

1. Sub-microsecond native timings were truncated. Each ScopedTimer sample was
   cast to whole microseconds before accumulation, so any call under 1 us
   contributed zero and high-frequency timers (SQLNumResultCols_wrap,
   construct_rows, etc.) under-reported or showed 0. PerfStats now accumulates
   in nanoseconds (int64, ~292 yr headroom) and get_stats() converts to
   fractional microseconds only at output. perf_timer.py get_stats() likewise
   emits fractional us. A single sub-us call now survives as e.g. 0.05 us
   instead of collapsing to 0.

2. FetchBatchData::cache_column_metadata stayed active through row
   construction. The PERF_TIMER was declared at function scope, so its RAII
   lifetime spanned the construct_rows loop and made metadata caching look like
   a dominant fetch cost. The per-batch setup loops are now wrapped in an inner
   block; construct_rows is timed separately. Verified live: on a 158-row query
   metadata = 9 us vs construct_rows = 138 us (previously metadata enclosed both).

Also: README direct-API example now calls disable() before reset(); the
vacuous run_script wall-time test is replaced with one that asserts a known
200 ms in-script sleep is reflected in wall_ms; added a deterministic test
proving five 300 ns samples accumulate to 1.5 us without truncation.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 07:43

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

There are a few concrete correctness/maintainability issues to address (notably exception re-raising that drops tracebacks, and strengthening the “compiled out” native-profiler guarantee).

Review details

Suppressed comments (5)

Previously missed (3) — in code that hasn't changed since the last review.

mssql_python/cursor.py:2823

  • raise e resets the traceback context, which makes debugging harder and can hide the original error location. Use bare raise to re-raise the current exception with its original traceback.

This issue also appears in the following locations of the same file:

  • line 2894
  • line 2959
    mssql_python/pybind/performance_counter.hpp:18
  • performance_counter.hpp unconditionally pulls in pybind11 and defines the full profiling implementation, and it’s included by core sources even when ENABLE_PROFILING is OFF. That means non-profiling builds still compile/parse the profiler machinery, which makes it harder to guarantee (and measure) “compiled out” behavior for release wheels and increases compile-time surface area. Consider guarding the implementation (and pybind11 includes) behind ENABLE_PROFILING (or moving it into a .cpp compiled only when profiling is enabled) and leaving only a no-op PERF_TIMER definition for non-profiling builds.
    mssql_python/cursor.py:1829
  • The exception variable e is not used in this handler; keeping it can trigger unused-variable linting and adds noise. Prefer except Exception: here.

mssql_python/cursor.py:2896

  • raise e resets the traceback context, which makes debugging harder and can hide the original error location. Use bare raise to re-raise the current exception with its original traceback.
        except Exception as e:
            # On error, don't increment rownumber - rethrow the error
            raise e

mssql_python/cursor.py:2961

  • raise e resets the traceback context, which makes debugging harder and can hide the original error location. Use bare raise to re-raise the current exception with its original traceback.
        except Exception as e:
            # On error, don't increment rownumber - rethrow the error
            raise e
  • Files reviewed: 18/18 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

Three except blocks added by the profiling commit re-raised with `raise e`,
which resets the traceback to the re-raise site and hides the original error
location. Use a bare `raise` (and drop the now-unused `as e`) so the original
traceback propagates. Flagged by review; the identical pre-existing sites in
main are left untouched.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 08:24

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

It touches core execute/fetch paths and native binding code across multiple layers/build configurations, so it warrants final human validation despite issues being minor.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

profiler/core.py:19

  • sys is imported but never used in this module, which can trigger lint warnings and adds unnecessary noise. Remove the unused import.
  • Files reviewed: 18/18 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

@bewithgaurav
Gaurav Sharma (bewithgaurav) marked this pull request as ready for review September 8, 2026 09:28
The top-level README had no pointer to the profiler. Add a short
'Performance profiling (internal)' subsection under Contributing that states
the profiler is off by default (no profiler code in released wheels) and links
to profiler/README.md so contributors can find the build-and-run guide.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 09:33

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Changes recommended

There is a functional issue in _ProfilingContext where per-window timeline enabling can be lost on collect(), and README documentation currently overstates that “released wheels contain no profiler code.”

Once you've addressed the issues Copilot identified, you can request another Copilot review.

Review details

Suppressed comments (1)

Previously missed (1) — in code that hasn't changed since the last review.

profiler/core.py:72

  • _ProfilingContext.enable(timeline=True) turns on timeline recording, but collect() only checks self._timeline_mode to decide whether to preserve timeline events (reset_stats_only vs reset). This means per-window timeline mode can be silently lost and timeline events cleared on collect() when set via the enable() argument.
  • Files reviewed: 19/19 changed files
  • Comments generated: 1
  • Review effort level: Lite

Comment thread README.md Outdated
… mode

Addresses the latest review:

- README overstated the compile-out guarantee. It said released wheels 'contain
  no profiler code', but this PR intentionally ships the thin Python-layer
  markers (perf_timer.py / perf_phase); only the native C++ instrumentation is
  compiled out. Narrow the wording to the native layer and note the Python
  markers ship as a no-op when profiling is disabled.
- Remove unused 'import sys' from profiler/core.py.
- _ProfilingContext.enable(timeline=True) turned timeline recording on but
  collect() consulted only _timeline_mode to decide whether to preserve timeline
  events, so a timeline requested via the enable() arg (without set_timeline())
  was silently dropped and the events cleared on collect(). enable() now persists
  the decision into _timeline_mode so the two paths can't diverge. Adds a
  regression test.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 8, 2026 09:44

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔵 Needs a closer look

It touches core query execution/fetch paths across both Python and native layers and adds new build-time gating, which warrants final human validation across platforms/build modes.

Review details
  • Files reviewed: 19/19 changed files
  • Comments generated: 0 new
  • Review effort level: Lite

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

pr-size: large Substantial code update

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants