FEAT: Profiler

[Gaurav Sharma (bewithgaurav)]

Work Item / Issue Reference

ADO Work Item: Fixed AB#44819

---

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.

• C++ layer: performance_counter.hpp adds a PERF_TIMER("name") RAII macro, instrumentation across ddbc_bindings.cpp and the connection sources, exposed to python as the ddbc_bindings.profiling submodule (enable/disable/get_stats/get_timeline/reset).
• python layer: perf_timer.py adds perf_phase("name") context managers around the execute/fetch phases in cursor.py. ddbc:: vs py:: prefixes tell you which layer a timer belongs to.
• runner: profiler/ CLI (python -m profiler --scenarios ...) with 10 built-in scenarios plus aggregate and timeline reports. the profiler/ package is dev-only and excluded from the shipped wheel; the runtime instrumentation it drives (perf_timer.py, the ddbc_bindings profiling submodule) is what ships.

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.

[github-actions]

📊 Code Coverage Report

🔥 Diff Coverage 63%

🎯 Overall Coverage 80%

📈 Total Lines Covered:6884 out of 8565 📁 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 (100%)
• mssql_python/pybind/connection/connection.cpp (100%)
• mssql_python/pybind/connection/connection_pool.cpp (100%)
• mssql_python/pybind/ddbc_bindings.cpp (68.9%): Missing lines 990-992,998-999,1389,1652,1716,1764,2692-2694,3167,4066
• mssql_python/pybind/performance_counter.hpp (1.3%): Missing lines 62-65,67-69,71-76,79-93,95-111,113-117,119-122,124-135,145-149,151-157

Summary

• Total: 260 lines
• Missing: 94 lines
• Coverage: 63%

mssql_python/cursor.py

Lines 1572-1582

1572column_metadata= []
1573try:
1574ddbc_bindings.DDBCSQLDescribeCol(self.hstmt, column_metadata)
1575self._initialize_description(column_metadata)
! 1576exceptExceptionase: # pylint: disable=broad-exception-caught1577# If describe fails, it's likely there are no results (e.g., for INSERT)
! 1578self.description=None15791580# Reset rownumber for new result set (only for SELECT statements)1581ifself.description: # If we have column descriptions, it's likely a SELECT1582self.rowcount=-1

---

mssql_python/pybind/ddbc_bindings.cpp

Lines 986-996

986ThrowStdException(errorString.str());
987 }
988 }
989assert(SQLBindParameter_ptr && SQLGetStmtAttr_ptr && SQLSetDescField_ptr);
! 990RETCODE rc;
! 991 {
! 992PERF_TIMER("BindParameters::SQLBindParameter_call");
993 rc = SQLBindParameter_ptr(
994 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */995static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
996static_cast<SQLSMALLINT>(paramInfo.paramCType),

---

Lines 994-1003

994 hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1), /* 1-based indexing */995static_cast<SQLUSMALLINT>(paramInfo.inputOutputType),
996static_cast<SQLSMALLINT>(paramInfo.paramCType),
997static_cast<SQLSMALLINT>(paramInfo.paramSQLType), paramInfo.columnSize,
! 998 paramInfo.decimalDigits, dataPtr, bufferLength, strLenOrIndPtr);
! 999 }
1000if (!SQL_SUCCEEDED(rc)) {
1001LOG("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

1385return instance;
1386 }
13871388voidDriverLoader::loadDriver() {
! 1389PERF_TIMER("DriverLoader::loadDriver");
1390std::call_once(m_onceFlag, [this]() {
1391LoadDriverOrThrowException();
1392 m_driverLoaded = true;
1393 });

---

Lines 1648-1656

16481649SQLRETURNSQLColumns_wrap(SqlHandlePtr StatementHandle, const py::object& catalogObj,
1650const py::object& schemaObj, const py::object& tableObj,
1651const py::object& columnObj) {
! 1652PERF_TIMER("SQLColumns_wrap");
1653if (!SQLColumns_ptr) {
1654ThrowStdException("SQLColumns function not loaded");
1655 }

---

Lines 1712-1720

1712return errorInfo;
1713 }
17141715 py::list SQLGetAllDiagRecords(SqlHandlePtr handle) {
! 1716PERF_TIMER("SQLGetAllDiagRecords");
1717LOG("SQLGetAllDiagRecords: Retrieving all diagnostic records for handle "1718"%p, handleType=%d",
1719 (void*)handle->get(), handle->type());
1720if (!SQLGetDiagRec_ptr) {

---

Lines 1760-1768

1760 }
17611762// Wrap SQLExecDirect1763SQLRETURNSQLExecDirect_wrap(SqlHandlePtr StatementHandle, const std::u16string& Query) {
! 1764PERF_TIMER("SQLExecDirect_wrap");
1765LOG("SQLExecDirect: Executing query directly - statement_handle=%p, "1766"query_length=%zu chars",
1767 (void*)StatementHandle->get(), Query.length());
1768if (!SQLExecDirect_ptr) {

---

Lines 2688-2698

2688RETCODE rc;
2689 {
2690PERF_TIMER("BindParameterArray::SQLBindParameter_call");
2691 rc = SQLBindParameter_ptr(hStmt, static_cast<SQLUSMALLINT>(paramIndex + 1),
! 2692static_cast<SQLUSMALLINT>(info.inputOutputType),
! 2693static_cast<SQLSMALLINT>(info.paramCType),
! 2694static_cast<SQLSMALLINT>(info.paramSQLType), info.columnSize,
2695 info.decimalDigits, dataPtr, bufferLength, strLenOrIndArray);
2696 }
2697if (!SQL_SUCCEEDED(rc)) {
2698LOG("BindParameterArray: SQLBindParameter failed - "

---

Lines 3163-3171

3163SQLRETURNSQLGetData_wrap(SqlHandlePtr StatementHandle, SQLUSMALLINT colCount, py::list& row,
3164const std::string& charEncoding = "utf-16le",
3165const std::string& wcharEncoding = "utf-16le",
3166int charCtype = SQL_C_WCHAR) {
! 3167PERF_TIMER("SQLGetData_wrap");
3168// Note: wcharEncoding parameter is reserved for future use3169// Currently WCHAR data always uses UTF-16LE for Windows compatibility3170 (void)wcharEncoding; // Suppress unused parameter warning

---

Lines 4062-4070

4062 ret);
4063return ret;
4064 }
4065// Pre-cache column metadata to avoid repeated dictionary lookups
! 4066PERF_TIMER("FetchBatchData::cache_column_metadata");
4067structColumnInfo {
4068SQLSMALLINT dataType;
4069SQLULEN columnSize;
4070SQLULEN processedColumnSize;

---

mssql_python/pybind/performance_counter.hpp

Lines 58-139

58bool timeline_enabled_ = false;
59 std::chrono::time_point<std::chrono::high_resolution_clock> epoch_;
6061public:
! 62static PerformanceCounter& instance() {
! 63static PerformanceCounter counter;
! 64return counter;
! 65 }
66 ! 67voidenable() { enabled_ = true; }
! 68voiddisable() { enabled_ = false; }
! 69boolis_enabled() const { return enabled_; }
70 ! 71voidenable_timeline() {
! 72 timeline_enabled_ = true;
! 73 epoch_ = std::chrono::high_resolution_clock::now();
! 74 }
! 75voiddisable_timeline() { timeline_enabled_ = false; }
! 76boolis_timeline_enabled() const { return timeline_enabled_; }
7778voidrecord(const std::string& name, int64_t duration_us,
! 79 std::chrono::time_point<std::chrono::high_resolution_clock> start) {
! 80if (!enabled_) return;
! 81 ! 82 std::lock_guard<std::mutex> lock(mutex_);
! 83auto& stats = counters_[name];
! 84 stats.total_time_us += duration_us;
! 85 stats.call_count++;
! 86 stats.min_time_us = std::min(stats.min_time_us, duration_us);
! 87 stats.max_time_us = std::max(stats.max_time_us, duration_us);
! 88 ! 89if (timeline_enabled_) {
! 90auto offset = std::chrono::duration_cast<std::chrono::microseconds>(start - epoch_).count();
! 91 timeline_.push_back({name, offset, duration_us});
! 92 }
! 93 }
94 ! 95 py::dict get_stats() {
! 96 std::lock_guard<std::mutex> lock(mutex_);
! 97 py::dict result;
! 98 ! 99for (constauto& [name, stats] : counters_) {
! 100 py::dict d;
! 101 d["total_us"] = stats.total_time_us;
! 102 d["calls"] = stats.call_count;
! 103 d["avg_us"] = stats.call_count > 0 ? stats.total_time_us / stats.call_count : 0;
! 104 d["min_us"] = stats.min_time_us == INT64_MAX ? 0 : stats.min_time_us;
! 105 d["max_us"] = stats.max_time_us;
! 106 d["platform"] = PROFILING_PLATFORM;
! 107 result[py::str(name)] = d;
! 108 }
! 109 ! 110return result;
! 111 }
112 ! 113voidreset() {
! 114 std::lock_guard<std::mutex> lock(mutex_);
! 115 counters_.clear();
! 116 timeline_.clear();
! 117 }
118 ! 119voidreset_stats_only() {
! 120 std::lock_guard<std::mutex> lock(mutex_);
! 121 counters_.clear();
! 122 }
123 ! 124 py::list get_timeline() {
! 125 std::lock_guard<std::mutex> lock(mutex_);
! 126 py::list result;
! 127for (constauto& ev : timeline_) {
! 128 py::dict d;
! 129 d["name"] = ev.name;
! 130 d["start_us"] = ev.start_us;
! 131 d["duration_us"] = ev.duration_us;
! 132 result.append(d);
! 133 }
! 134return result;
! 135 }
136 };
137138// RAII timer - automatically records on destruction139classScopedTimer {

---

Lines 141-161

141constchar* name_;
142 std::chrono::time_point<std::chrono::high_resolution_clock> start_;
143144public:
! 145explicitScopedTimer(constchar* name) : name_(name) {
! 146if (PerformanceCounter::instance().is_enabled()) {
! 147 start_ = std::chrono::high_resolution_clock::now();
! 148 }
! 149 }
150 ! 151~ScopedTimer() {
! 152if (PerformanceCounter::instance().is_enabled()) {
! 153auto end = std::chrono::high_resolution_clock::now();
! 154auto duration = std::chrono::duration_cast<std::chrono::microseconds>(end - start_).count();
! 155PerformanceCounter::instance().record(name_, duration, start_);
! 156 }
! 157 }
158 };
159160 } // namespace mssql_profiling

---

---

📋 Files Needing Attention

📉 Files with overall lowest coverage (click to expand)

mssql_python.pybind.performance_counter.hpp: 1.2%
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.4%
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%

---

🔗 Quick Links

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