FEAT: Profiler

mssql_python/perf_timer.py

@@ -0,0 +1,134 @@
+# Copyright (c) Microsoft Corporation.
+# Licensed under the MIT license.
+"""
+Lightweight phase-level profiling for the Python layer.
+
+Usage in cursor.py:
+    from mssql_python.perf_timer import perf_phase
+
+    with perf_phase("py::execute::param_type_detection"):
+        ...
+
+Control from profiler script:
+    from mssql_python.perf_timer import enable, disable, get_stats, reset
+
+Stats dict matches the C++ profiling format so both layers can be
+printed with the same reporter. Entries use a "py::" prefix to
+distinguish from C++ timers.
+"""
+
+import time
+from contextlib import contextmanager
+
+_enabled = False
+_stats: dict[str, dict] = {}
+_timeline: list[dict] = []
+_timeline_enabled = False
+_epoch_ns: int = 0
+
+
+def enable():
+    global _enabled
+    _enabled = True
+
+
+def disable():
+    global _enabled
+    _enabled = False
+
+
+def is_enabled() -> bool:
+    return _enabled
+
+
+def reset():
+    _stats.clear()
+    _timeline.clear()
+
+
+def reset_stats_only():
+    _stats.clear()
+
+
+def enable_timeline():
+    global _timeline_enabled, _epoch_ns
+    _timeline_enabled = True
+    _epoch_ns = time.perf_counter_ns()
+
+
+def disable_timeline():
+    global _timeline_enabled
+    _timeline_enabled = False
+
+
+def get_timeline() -> list[dict]:
+    return [
+        {
+            "name": ev["name"],
+            "start_us": ev["start_ns"] // 1000,
+            "duration_us": ev["duration_ns"] // 1000,
+        }
+        for ev in _timeline
+    ]
+
+
+def get_stats() -> dict:
+    out = {}
+    for name, s in _stats.items():
+        out[name] = {
+            "calls": s["calls"],
+            "total_us": s["total_ns"] // 1000,
+            "min_us": s["min_ns"] // 1000,
+            "max_us": s["max_ns"] // 1000,
+        }
+    return out
+
+
+@contextmanager
+def perf_phase(name: str):
+    if not _enabled:
+        yield
+        return
+    t0 = time.perf_counter_ns()
+    yield
+    elapsed = time.perf_counter_ns() - t0
+    _record(name, elapsed, t0)
+
+
+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)
+
+
+def _record(name: str, elapsed: int, start_ns: int = 0):
+    entry = _stats.get(name)
+    if entry is None:
+        _stats[name] = {
+            "calls": 1,
+            "total_ns": elapsed,
+            "min_ns": elapsed,
+            "max_ns": elapsed,
+        }
+    else:
+        entry["calls"] += 1
+        entry["total_ns"] += elapsed
+        if elapsed < entry["min_ns"]:
+            entry["min_ns"] = elapsed
+        if elapsed > entry["max_ns"]:
+            entry["max_ns"] = elapsed
+
+    if _timeline_enabled and start_ns:
+        _timeline.append(
+            {
+                "name": name,
+                "start_ns": start_ns - _epoch_ns,
+                "duration_ns": elapsed,
+            }
+        )

mssql_python/pybind/connection/connection.cpp

@@ -17,6 +17,7 @@
 
 // Logging uses LOG() macro for all diagnostic output
 #include "logger_bridge.hpp"
+#include "performance_counter.hpp"
 
 static SqlHandlePtr getEnvHandle() {
     static SqlHandlePtr envHandle = []() -> SqlHandlePtr {
@@ -48,6 +49,7 @@ static SqlHandlePtr getEnvHandle() {
 //-------------------------------------------------------------------------------------------------
 Connection::Connection(const std::u16string& conn_str, bool use_pool)
     : _connStr(conn_str), _autocommit(false), _fromPool(use_pool) {
+    PERF_TIMER("Connection::Connection");
     allocateDbcHandle();
 }
 
@@ -57,6 +59,7 @@ Connection::~Connection() {
 
 // Allocates connection handle
 void Connection::allocateDbcHandle() {
+    PERF_TIMER("Connection::allocateDbcHandle");
     auto _envHandle = getEnvHandle();
     SQLHANDLE dbc = nullptr;
     LOG("Allocating SQL Connection Handle");
@@ -66,6 +69,7 @@ void Connection::allocateDbcHandle() {
 }
 
 void Connection::connect(const py::dict& attrs_before) {
+    PERF_TIMER("Connection::connect");
     LOG("Connecting to database");
     // Apply access token before connect
     if (!attrs_before.is_none() && py::len(attrs_before) > 0) {
@@ -83,6 +87,7 @@ void Connection::connect(const py::dict& attrs_before) {
         // and SQL Server authentication — all pure I/O that doesn't need the GIL.
         // This allows other Python threads to run concurrently.
         py::gil_scoped_release release;
+        PERF_TIMER("Connection::connect::SQLDriverConnect_call");
         ret = SQLDriverConnect_ptr(_dbcHandle->get(), nullptr, connStrPtr, SQL_NTS, nullptr,
                                    0, nullptr, SQL_DRIVER_NOPROMPT);
     }
@@ -91,6 +96,7 @@ void Connection::connect(const py::dict& attrs_before) {
 }
 
 void Connection::disconnect() {
+    PERF_TIMER("Connection::disconnect");
     if (_dbcHandle) {
         LOG("Disconnecting from database");
 
@@ -185,6 +191,7 @@ void Connection::checkError(SQLRETURN ret) const {
 }
 
 void Connection::commit() {
+    PERF_TIMER("Connection::commit");
     if (!_dbcHandle) {
         ThrowStdException("Connection handle not allocated");
     }
@@ -200,6 +207,7 @@ void Connection::commit() {
 }
 
 void Connection::rollback() {
+    PERF_TIMER("Connection::rollback");
     if (!_dbcHandle) {
         ThrowStdException("Connection handle not allocated");
     }
@@ -215,6 +223,7 @@ void Connection::rollback() {
 }
 
 void Connection::setAutocommit(bool enable) {
+    PERF_TIMER("Connection::setAutocommit");
     if (!_dbcHandle) {
         ThrowStdException("Connection handle not allocated");
     }
@@ -253,6 +262,7 @@ bool Connection::getAutocommit() const {
 }
 
 SqlHandlePtr Connection::allocStatementHandle() {
+    PERF_TIMER("Connection::allocStatementHandle");
     if (!_dbcHandle) {
         ThrowStdException("Connection handle not allocated");
     }
@@ -516,6 +526,7 @@ std::chrono::steady_clock::time_point Connection::lastUsed() const {
 ConnectionHandle::ConnectionHandle(const std::u16string& connStr, bool usePool,
                                    const py::dict& attrsBefore)
     : _usePool(usePool), _connStr(connStr) {
+    PERF_TIMER("ConnectionHandle::ConnectionHandle");
     if (_usePool) {
         _conn = ConnectionPoolManager::getInstance().acquireConnection(_connStr, attrsBefore);
     } else {
@@ -531,6 +542,7 @@ ConnectionHandle::~ConnectionHandle() {
 }
 
 void ConnectionHandle::close() {
+    PERF_TIMER("ConnectionHandle::close");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
@@ -543,20 +555,23 @@ void ConnectionHandle::close() {
 }
 
 void ConnectionHandle::commit() {
+    PERF_TIMER("ConnectionHandle::commit");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
     _conn->commit();
 }
 
 void ConnectionHandle::rollback() {
+    PERF_TIMER("ConnectionHandle::rollback");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
     _conn->rollback();
 }
 
 void ConnectionHandle::setAutocommit(bool enabled) {
+    PERF_TIMER("ConnectionHandle::setAutocommit");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
@@ -571,6 +586,7 @@ bool ConnectionHandle::getAutocommit() const {
 }
 
 SqlHandlePtr ConnectionHandle::allocStatementHandle() {
+    PERF_TIMER("ConnectionHandle::allocStatementHandle");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
@@ -635,13 +651,15 @@ py::object Connection::getInfo(SQLUSMALLINT infoType) const {
 }
 
 py::object ConnectionHandle::getInfo(SQLUSMALLINT infoType) const {
+    PERF_TIMER("ConnectionHandle::getInfo");
     if (!_conn) {
         ThrowStdException("Connection object is not initialized");
     }
     return _conn->getInfo(infoType);
 }
 
 void ConnectionHandle::setAttr(int attribute, py::object value) {
+    PERF_TIMER("ConnectionHandle::setAttr");
     if (!_conn) {
         ThrowStdException("Connection not established");
     }

mssql_python/pybind/connection/connection_pool.cpp

@@ -8,12 +8,14 @@
 
 // Logging uses LOG() macro for all diagnostic output
 #include "logger_bridge.hpp"
+#include "performance_counter.hpp"
 
 ConnectionPool::ConnectionPool(size_t max_size, int idle_timeout_secs)
     : _max_size(max_size), _idle_timeout_secs(idle_timeout_secs), _current_size(0) {}
 
 std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connStr,
                                                     const py::dict& attrs_before) {
+    PERF_TIMER("ConnectionPool::acquire");
     std::vector<std::shared_ptr<Connection>> to_disconnect;
     std::shared_ptr<Connection> valid_conn = nullptr;
     bool needs_connect = false;
@@ -120,6 +122,7 @@ std::shared_ptr<Connection> ConnectionPool::acquire(const std::u16string& connSt
 }
 
 void ConnectionPool::release(std::shared_ptr<Connection> conn) {
+    PERF_TIMER("ConnectionPool::release");
     bool should_disconnect = false;
     {
         std::lock_guard<std::mutex> lock(_mutex);
@@ -145,6 +148,7 @@ void ConnectionPool::release(std::shared_ptr<Connection> conn) {
 }
 
 void ConnectionPool::close() {
+    PERF_TIMER("ConnectionPool::close");
     std::vector<std::shared_ptr<Connection>> to_close;
     {
         std::lock_guard<std::mutex> lock(_mutex);
@@ -170,6 +174,7 @@ ConnectionPoolManager& ConnectionPoolManager::getInstance() {
 
 std::shared_ptr<Connection> ConnectionPoolManager::acquireConnection(const std::u16string& connStr,
                                                                      const py::dict& attrs_before) {
+    PERF_TIMER("ConnectionPoolManager::acquireConnection");
     std::shared_ptr<ConnectionPool> pool;
     {
         std::lock_guard<std::mutex> lock(_manager_mutex);