FEAT: Profiler - #552
Conversation
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
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>
📊 Code Coverage Report
Diff CoverageDiff: main...HEAD, staged and unstaged changes
Summary
mssql_python/cursor.pyLines 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.pyLines 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.cppLines 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.cppLines 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 simplifiesmssql_python/pybind/performance_counter.hppLines 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
|
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>
There was a problem hiding this comment.
🟡 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 inCursor.execute()/executemany()/fetch*(). - Adds a C++ RAII timing macro (
PERF_TIMER) + global counter/timeline, and exposes it asmssql_python.ddbc_bindings.profilingin profiling-enabled builds. - Adds a dev-only
profiler/CLI + scenarios/reporting, and excludes it from the shipped wheel viasetup.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.
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>
There was a problem hiding this comment.
🔵 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
PerformanceCounterusesint64_t,INT64_MAX, andstd::min/std::maxbut 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:199Profiler.run_script()leaks the cursor (and leaves profiling enabled) if the user script fails to compile or raises duringexec(), because cleanup only happens on the success path. Wrap execution intry/finallysocursor.close()andself._ctx.collect()always run.
profiler/init.py:17- The module docstring shows
p.report(), butProfilerdoesn’t define areportmethod (and there’s nodef report(...)anywhere underprofiler/). This example will fail if copied.
mssql_python/perf_timer.py:108
perf_start()returns 0 when profiling is disabled, butperf_stop()will record a bogus duration if profiling gets enabled between start and stop (it will computenow - 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>
There was a problem hiding this comment.
🟡 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
…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>
There was a problem hiding this comment.
🔵 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>
There was a problem hiding this comment.
🔵 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()usesperf_start()/perf_stop()around the parameter-type-detection loop, butperf_stop()is not in afinally(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 (asperf_phase()does). Consider switching this section towith perf_phase("py::executemany::param_type_detection"):or wrapping the loop intry/finallysoperf_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>
There was a problem hiding this comment.
🔵 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_unpacknow 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
eis not used in thisDDBCSQLDescribeColfailure 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
SQLBindColumscontains 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>
There was a problem hiding this comment.
🔵 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 eresets the traceback context, which makes debugging harder and can hide the original error location. Use bareraiseto 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
eis not used in this handler; keeping it can trigger unused-variable linting and adds noise. Preferexcept Exception:here.
mssql_python/cursor.py:2896
raise eresets the traceback context, which makes debugging harder and can hide the original error location. Use bareraiseto 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 eresets the traceback context, which makes debugging harder and can hide the original error location. Use bareraiseto 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>
There was a problem hiding this comment.
🔵 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
sysis 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
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>
There was a problem hiding this comment.
🟡 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
… 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>
There was a problem hiding this comment.
🔵 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
Work Item / Issue Reference
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
ENABLE_PROFILINGCMake option, off by default. Normal builds expand everyPERF_TIMERto a no-op and do not register the nativeddbc_bindings.profilingsubmodule, so there is no native profiler code, no unwind tables, and no runtime branch in the released binary. Internal/dev builds opt in withENABLE_PROFILING=1 bash build.sh(orset ENABLE_PROFILING=1+build.baton Windows).perf_timer.pyand theperf_phase(...)markers incursor.py) cannot be compiled out the same way, so it ships. When profiling is disabled,perf_phasereturns 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 thefetchoneloop), 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)
performance_counter.hppprovides aPERF_TIMER("name")RAII macro and instrumentsddbc_bindings.cppand the connection sources, exposed to Python as theddbc_bindings.profilingsubmodule.perf_timer.pyprovidesperf_phase("name")context managers around the execute/fetch phases incursor.py. Theddbc::andpy::prefixes identify which layer a timer belongs to.profiler/CLI (python -m profiler) with built-in scenarios plus aggregate and timeline reports, and a--scriptflag 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.pycovers both layers (Pythonperf_timerand, when built with profiling, theddbc_bindings.profilingsubmodule). 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:
ENABLE_PROFILING, so the profiling build and its native-layer tests are not exercised in CI. A follow-up will add anENABLE_PROFILINGbuild/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.Everything gated behind
ENABLE_PROFILING(off by default) means neither deferral affects released wheels today.