FEAT: Profiler#552
Draft
bewithgaurav wants to merge 11 commits into
Draft
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>
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
| self.rowcount = ddbc_bindings.DDBCSQLRowCount(self.hstmt) | ||
| with perf_phase("py::execute::post_execute"): | ||
| # Update rowcount after execution | ||
| # TODO: rowcount return code from SQL needs to be handled |
|
|
||
| from profiler import Profiler | ||
|
|
||
| p = Profiler("Server=localhost,1433;UID=sa;Pwd=...;Encrypt=no;TrustServerCertificate=yes;") |
📊 Code Coverage Report
Diff CoverageDiff: main...HEAD, staged and unstaged changes
Summary
mssql_python/cursor.pyLines 1572-1582 1572 column_metadata = []
1573 try:
1574 ddbc_bindings.DDBCSQLDescribeCol(self.hstmt, column_metadata)
1575 self._initialize_description(column_metadata)
! 1576 except Exception as e: # pylint: disable=broad-exception-caught
1577 # If describe fails, it's likely there are no results (e.g., for INSERT)
! 1578 self.description = None
1579
1580 # Reset rownumber for new result set (only for SELECT statements)
1581 if self.description: # If we have column descriptions, it's likely a SELECT
1582 self.rowcount = -1mssql_python/perf_timer.pyLines 121-129 121 entry["total_ns"] += elapsed
122 if elapsed < entry["min_ns"]:
123 entry["min_ns"] = elapsed
124 if elapsed > entry["max_ns"]:
! 125 entry["max_ns"] = elapsed
126
127 if _timeline_enabled and start_ns:
128 _timeline.append(
129 {mssql_python/pybind/ddbc_bindings.cppLines 986-996 986 ThrowStdException(errorString.str());
987 }
988 }
989 assert(SQLBindParameter_ptr && SQLGetStmtAttr_ptr && SQLSetDescField_ptr);
! 990 RETCODE rc;
! 991 {
! 992 PERF_TIMER("BindParameters::SQLBindParameter_call");
993 rc = SQLBindParameter_ptr(
994 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */
995 static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
996 static_cast<SQLSMALLINT>(paramInfo.paramCType),Lines 994-1003 994 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */
995 static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
996 static_cast<SQLSMALLINT>(paramInfo.paramCType),
997 static_cast<SQLSMALLINT>(paramInfo.paramSQLType), paramInfo.columnSize,
! 998 paramInfo.decimalDigits, dataPtr, bufferLength, strLenOrIndPtr);
! 999 }
1000 if (!SQL_SUCCEEDED(rc)) {
1001 LOG("BindParameters: SQLBindParameter failed for param[%d] - "
1002 "SQLRETURN=%d, C_Type=%d, SQL_Type=%d",
1003 paramIndex, rc, paramInfo.paramCType, paramInfo.paramSQLType);Lines 1385-1393 1385 return instance;
1386 }
1387
1388 void DriverLoader::loadDriver() {
! 1389 PERF_TIMER("DriverLoader::loadDriver");
1390 std::call_once(m_onceFlag, [this]() {
1391 LoadDriverOrThrowException();
1392 m_driverLoaded = true;
1393 });Lines 1648-1656 1648
1649 SQLRETURN SQLColumns_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj,
1650 const py::object& schemaObj, const py::object& tableObj,
1651 const py::object& columnObj) {
! 1652 PERF_TIMER("SQLColumns_wrap");
1653 if (!SQLColumns_ptr) {
1654 ThrowStdException("SQLColumns function not loaded");
1655 }Lines 1712-1720 1712 return errorInfo;
1713 }
1714
1715 py::list SQLGetAllDiagRecords(SqlHandlePtr handle) {
! 1716 PERF_TIMER("SQLGetAllDiagRecords");
1717 LOG("SQLGetAllDiagRecords: Retrieving all diagnostic records for handle "
1718 "%p, handleType=%d",
1719 (void*)handle->get(), handle->type());
1720 if (!SQLGetDiagRec_ptr) {Lines 1760-1768 1760 }
1761
1762 // Wrap SQLExecDirect
1763 SQLRETURN SQLExecDirect_wrap(SqlHandlePtr StatementHandle, const std::u16string& Query) {
! 1764 PERF_TIMER("SQLExecDirect_wrap");
1765 LOG("SQLExecDirect: Executing query directly - statement_handle=%p, "
1766 "query_length=%zu chars",
1767 (void*)StatementHandle->get(), Query.length());
1768 if (!SQLExecDirect_ptr) {Lines 2688-2698 2688 RETCODE rc;
2689 {
2690 PERF_TIMER("BindParameterArray::SQLBindParameter_call");
2691 rc = SQLBindParameter_ptr(hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1),
! 2692 static_cast<SQLUSMALLINT>(info.inputOutputType),
! 2693 static_cast<SQLSMALLINT>(info.paramCType),
! 2694 static_cast<SQLSMALLINT>(info.paramSQLType), info.columnSize,
2695 info.decimalDigits, dataPtr, bufferLength, strLenOrIndArray);
2696 }
2697 if (!SQL_SUCCEEDED(rc)) {
2698 LOG("BindParameterArray: SQLBindParameter failed - "Lines 3163-3171 3163 SQLRETURN SQLGetData_wrap(SqlHandlePtr StatementHandle, SQLUSMALLINT colCount, py::list& row,
3164 const std::string& charEncoding = "utf-16le",
3165 const std::string& wcharEncoding = "utf-16le",
3166 int charCtype = SQL_C_WCHAR) {
! 3167 PERF_TIMER("SQLGetData_wrap");
3168 // Note: wcharEncoding parameter is reserved for future use
3169 // Currently WCHAR data always uses UTF-16LE for Windows compatibility
3170 (void)wcharEncoding; // Suppress unused parameter warningLines 4062-4070 4062 ret);
4063 return ret;
4064 }
4065 // Pre-cache column metadata to avoid repeated dictionary lookups
! 4066 PERF_TIMER("FetchBatchData::cache_column_metadata");
4067 struct ColumnInfo {
4068 SQLSMALLINT dataType;
4069 SQLULEN columnSize;
4070 SQLULEN processedColumnSize;mssql_python/pybind/performance_counter.hppLines 72-80 72 timeline_enabled_ = true;
73 epoch_ = std::chrono::high_resolution_clock::now();
74 }
75 void disable_timeline() { timeline_enabled_ = false; }
! 76 bool is_timeline_enabled() const { return timeline_enabled_; }
77
78 void record(const std::string& name, int64_t duration_us,
79 std::chrono::time_point<std::chrono::high_resolution_clock> start) {
80 if (!enabled_) return;📋 Files Needing Attention📉 Files with overall lowest coverage (click to expand)mssql_python.pybind.logger_bridge.cpp: 59.2%
mssql_python.pybind.ddbc_bindings.h: 59.9%
mssql_python.pybind.logger_bridge.hpp: 70.8%
mssql_python.pybind.ddbc_bindings.cpp: 76.5%
mssql_python.__init__.py: 77.3%
mssql_python.row.py: 77.6%
mssql_python.ddbc_bindings.py: 79.6%
mssql_python.pybind.connection.connection_pool.cpp: 80.4%
mssql_python.connection.py: 83.6%
mssql_python.logging.py: 85.5%🔗 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>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Work Item / Issue Reference
Summary
adds a two-layer performance profiler for diagnosing driver slowness across the python and native layers. off by default. the intended use is field diagnostics too: when a user reports a slow query, they can enable profiling, reproduce, and send back a dump that breaks the time down by phase, including inside the native code that a python sampling profiler sees as one opaque block.
overhead when off (the default): measured on macOS/arm64 against SQL Server 2022, end-to-end workloads (execute+fetchall, fetchmany, fetchone loops) show no difference vs a no-profiler build. deltas stay within run-to-run noise and the branch is often faster. the per-call cost of a disabled timer is microseconds, orders of magnitude below per-row DB latency, so it does not surface in real workloads. C++ timers early-return before doing any work when disabled.
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.
merged latest main and re-applied the instrumentation on top of the u16string migration and the issue #531 fetch changes. added tests/test_025_profiler.py covering both layers.