FEAT: Profiler by bewithgaurav · Pull Request #552 · microsoft/mssql-python

bewithgaurav · 2026-04-30T15:09:24Z

Work Item / Issue Reference

AB#<WORK_ITEM_ID>

GitHub Issue: #<ISSUE_NUMBER>

Summary

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>

-        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;")


github-actions · 2026-07-06T10:00:20Z

📊 Code Coverage Report

🔥 Diff Coverage 56%	🎯 Overall Coverage 80%	📈 Total Lines Covered: `6880` out of `8566` 📁 Project: `mssql-python`

Diff Coverage

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

mssql_python/cursor.py (96.7%): Missing lines 1576,1578
mssql_python/perf_timer.py (47.5%): Missing lines 32,37,41,45-46,50,55-56,61,65,76-78,84,92-95,101,107,111-113,120-125,127-128
mssql_python/pybind/connection/connection.cpp (100%)
mssql_python/pybind/connection/connection_pool.cpp (100%)
mssql_python/pybind/ddbc_bindings.cpp (68.2%): Missing lines 990-992,998-999,1389,1652,1716,1764,2692-2694,3167,4066
mssql_python/pybind/performance_counter.hpp (17.9%): Missing lines 24,59-60,63-68,71-72,74-79,81-85,87-89,91-100,102-103,105-109,111-114,116-127,139-140,145-148

Summary

Total: 258 lines
Missing: 111 lines
Coverage: 56%

mssql_python/cursor.py

Lines 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 = -1

mssql_python/perf_timer.py

Lines 28-69

  28 
  29 
  30 def enable():
  31     global _enabled
! 32     _enabled = True
  33 
  34 
  35 def disable():
  36     global _enabled
! 37     _enabled = False
  38 
  39 
  40 def is_enabled() -> bool:
! 41     return _enabled
  42 
  43 
  44 def reset():
! 45     _stats.clear()
! 46     _timeline.clear()
  47 
  48 
  49 def reset_stats_only():
! 50     _stats.clear()
  51 
  52 
  53 def enable_timeline():
  54     global _timeline_enabled, _epoch_ns
! 55     _timeline_enabled = True
! 56     _epoch_ns = time.perf_counter_ns()
  57 
  58 
  59 def disable_timeline():
  60     global _timeline_enabled
! 61     _timeline_enabled = False
  62 
  63 
  64 def get_timeline() -> list[dict]:
! 65     return [
  66         {
  67             "name": ev["name"],
  68             "start_us": ev["start_ns"] // 1000,
  69             "duration_us": ev["duration_ns"] // 1000,

Lines 72-82

  72     ]
  73 
  74 
  75 def get_stats() -> dict:
! 76     out = {}
! 77     for name, s in _stats.items():
! 78         out[name] = {
  79             "calls": s["calls"],
  80             "total_us": s["total_ns"] // 1000,
  81             "min_us": s["min_ns"] // 1000,
  82             "max_us": s["max_ns"] // 1000,

Lines 80-88

  80             "total_us": s["total_ns"] // 1000,
  81             "min_us": s["min_ns"] // 1000,
  82             "max_us": s["max_ns"] // 1000,
  83         }
! 84     return out
  85 
  86 
  87 @contextmanager
  88 def perf_phase(name: str):

Lines 88-99

  88 def perf_phase(name: str):
  89     if not _enabled:
  90         yield
  91         return
! 92     t0 = time.perf_counter_ns()
! 93     yield
! 94     elapsed = time.perf_counter_ns() - t0
! 95     _record(name, elapsed, t0)
  96 
  97 
  98 def perf_start() -> int:
  99     if not _enabled:

Lines 97-105

   97 
   98 def perf_start() -> int:
   99     if not _enabled:
  100         return 0
! 101     return time.perf_counter_ns()
  102 
  103 
  104 def perf_stop(name: str, t0: int):
  105     if not _enabled:

Lines 103-117

  103 
  104 def perf_stop(name: str, t0: int):
  105     if not _enabled:
  106         return
! 107     _record(name, time.perf_counter_ns() - t0, t0)
  108 
  109 
  110 def _record(name: str, elapsed: int, start_ns: int = 0):
! 111     entry = _stats.get(name)
! 112     if entry is None:
! 113         _stats[name] = {
  114             "calls": 1,
  115             "total_ns": elapsed,
  116             "min_ns": elapsed,
  117             "max_ns": elapsed,

Lines 116-132

  116             "min_ns": elapsed,
  117             "max_ns": elapsed,
  118         }
  119     else:
! 120         entry["calls"] += 1
! 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             {
  130                 "name": name,
  131                 "start_ns": start_ns - _epoch_ns,
  132                 "duration_ns": elapsed,

mssql_python/pybind/ddbc_bindings.cpp

Lines 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 warning

Lines 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.hpp

Lines 20-28

  20 // Platform detection
  21 #if defined(_WIN32) || defined(_WIN64)
  22     #define PROFILING_PLATFORM "windows"
  23 #elif defined(__linux__)
! 24     #define PROFILING_PLATFORM "linux"
  25 #elif defined(__APPLE__) || defined(__MACH__)
  26     #define PROFILING_PLATFORM "macos"
  27 #else
  28     #define PROFILING_PLATFORM "unknown"

Lines 55-131

   55         static PerformanceCounter counter;
   56         return counter;
   57     }
   58 
!  59     void enable() { enabled_ = true; }
!  60     void disable() { enabled_ = false; }
   61     bool is_enabled() const { return enabled_; }
   62 
!  63     void enable_timeline() {
!  64         timeline_enabled_ = true;
!  65         epoch_ = std::chrono::high_resolution_clock::now();
!  66     }
!  67     void disable_timeline() { timeline_enabled_ = false; }
!  68     bool is_timeline_enabled() const { return timeline_enabled_; }
   69 
   70     void record(const std::string& name, int64_t duration_us,
!  71                 std::chrono::time_point<std::chrono::high_resolution_clock> start) {
!  72         if (!enabled_) return;
   73         
!  74         std::lock_guard<std::mutex> lock(mutex_);
!  75         auto& stats = counters_[name];
!  76         stats.total_time_us += duration_us;
!  77         stats.call_count++;
!  78         stats.min_time_us = std::min(stats.min_time_us, duration_us);
!  79         stats.max_time_us = std::max(stats.max_time_us, duration_us);
   80 
!  81         if (timeline_enabled_) {
!  82             auto offset = std::chrono::duration_cast<std::chrono::microseconds>(start - epoch_).count();
!  83             timeline_.push_back({name, offset, duration_us});
!  84         }
!  85     }
   86 
!  87     py::dict get_stats() {
!  88         std::lock_guard<std::mutex> lock(mutex_);
!  89         py::dict result;
   90         
!  91         for (const auto& [name, stats] : counters_) {
!  92             py::dict d;
!  93             d["total_us"] = stats.total_time_us;
!  94             d["calls"] = stats.call_count;
!  95             d["avg_us"] = stats.call_count > 0 ? stats.total_time_us / stats.call_count : 0;
!  96             d["min_us"] = stats.min_time_us == INT64_MAX ? 0 : stats.min_time_us;
!  97             d["max_us"] = stats.max_time_us;
!  98             d["platform"] = PROFILING_PLATFORM;
!  99             result[py::str(name)] = d;
! 100         }
  101         
! 102         return result;
! 103     }
  104 
! 105     void reset() {
! 106         std::lock_guard<std::mutex> lock(mutex_);
! 107         counters_.clear();
! 108         timeline_.clear();
! 109     }
  110 
! 111     void reset_stats_only() {
! 112         std::lock_guard<std::mutex> lock(mutex_);
! 113         counters_.clear();
! 114     }
  115 
! 116     py::list get_timeline() {
! 117         std::lock_guard<std::mutex> lock(mutex_);
! 118         py::list result;
! 119         for (const auto& ev : timeline_) {
! 120             py::dict d;
! 121             d["name"] = ev.name;
! 122             d["start_us"] = ev.start_us;
! 123             d["duration_us"] = ev.duration_us;
! 124             result.append(d);
! 125         }
! 126         return result;
! 127     }
  128 };
  129 
  130 // RAII timer - automatically records on destruction
  131 class ScopedTimer {

Lines 135-152

  135     
  136 public:
  137     explicit ScopedTimer(const char* name) : name_(name) {
  138         if (PerformanceCounter::instance().is_enabled()) {
! 139             start_ = std::chrono::high_resolution_clock::now();
! 140         }
  141     }
  142     
  143     ~ScopedTimer() {
  144         if (PerformanceCounter::instance().is_enabled()) {
! 145             auto end = std::chrono::high_resolution_clock::now();
! 146             auto duration = std::chrono::duration_cast<std::chrono::microseconds>(end - start_).count();
! 147             PerformanceCounter::instance().record(name_, duration, start_);
! 148         }
  149     }
  150 };
  151 
  152 } // namespace mssql_profiling

📋 Files Needing Attention

📉 Files with overall lowest coverage (click to expand)

mssql_python.pybind.performance_counter.hpp: 17.9%
mssql_python.perf_timer.py: 48.3%
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%

🔗 Quick Links

⚙️ Build Summary	📋 Coverage Details
View Azure DevOps Build	Browse Full Coverage Report

bewithgaurav and others added 4 commits April 9, 2026 00:05

DOC: Add latest status update for profiler branch

1eb6650

my_bench and delete run_profiler

0a23cf9

bewithgaurav changed the title ~~Bewithgaurav/profiling~~ FEAT: Profiler May 7, 2026

bewithgaurav and others added 3 commits July 6, 2026 15:07

github-advanced-security AI found potential problems Jul 6, 2026

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

FEAT: Profiler#552

FEAT: Profiler#552
bewithgaurav wants to merge 7 commits into
mainfrom
bewithgaurav/profiling

bewithgaurav commented Apr 30, 2026

Uh oh!

github-actions Bot commented Jul 6, 2026

🔥 Diff Coverage

56%

🎯 Overall Coverage

80%

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants


		from profiler import Profiler

		p = Profiler("Server=localhost,1433;UID=sa;Pwd=...;Encrypt=no;TrustServerCertificate=yes;")

Uh oh!

Conversation

bewithgaurav commented Apr 30, 2026

Work Item / Issue Reference

Summary

Uh oh!

github-actions Bot commented Jul 6, 2026

📊 Code Coverage Report

🔥 Diff Coverage

56%

🎯 Overall Coverage

80%

Diff Coverage

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

Summary

mssql_python/cursor.py

mssql_python/perf_timer.py

mssql_python/pybind/ddbc_bindings.cpp

mssql_python/pybind/performance_counter.hpp

📋 Files Needing Attention

🔗 Quick Links

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants