Skip to content

PERF: Guard disabled debug logging in fetchval only - #823

Open
Jahnvi Thakkar (jahnvi480) wants to merge 3 commits into
mainfrom
jahnvi/scalar-fetch-logging-guard
Open

Jahnvi Thakkar (jahnvi480) wants to merge 3 commits into
mainfrom
jahnvi/scalar-fetch-logging-guard

Conversation

@jahnvi480

@jahnvi480 Jahnvi Thakkar (jahnvi480) commented Sep 28, 2026 •

Copy link
Copy Markdown
Contributor

Work Item / Issue Reference

AB#48364


Summary

This fix applies only to Cursor.fetchval(). It is not a general fix for fetch performance.

Add the existing logger.is_debug_enabled guard at each of the four fetchval debug call sites, avoiding logger.debug dispatch when debug logging is disabled. Check the flag separately at each call site so a logging-level change during self.fetchone() is observed by the success/EOF message.

Preserve existing messages, exception order, self.fetchone() dispatch, scalar return values, row consumption, and EOF behavior. fetchone, fetchmany, iteration, Row, converters, UUID handling, the logger implementation, and native code are unchanged. The production change is four added guard lines.

Strengthen the existing test_fetchval_basic_functionality test with a local mocked module logger: disabled dispatch, exact enabled messages for success/EOF/non-result statements, and both directions of logging-flag changes during the real fetchone() call. No new test functions, fixtures, or dependencies.

Performance scope and limitations

Bounded local measurements showed a fetchval benefit, and separate profiles confirmed that its disabled-debug debug/_log calls were eliminated while public fetch, Python-visible native-entry, and Row operation counts stayed unchanged. Profiling is attribution evidence, not a prediction of latency savings.

Unchanged fetchone controls remained slower in the candidate arms. Same-code A/A measurements also varied, but that does not explain away or justify subtracting the adverse control results. Broader performance qualification and the control cause remain unresolved. The evidence does not establish universal no-regression or merge/performance clearance.

Guard each fetchval debug call with the current cached debug flag and strengthen the existing fetchval basic-functionality test. Leave other fetch APIs and Row/native code unchanged.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot AI lite review requested due to automatic review settings September 28, 2026 10:31
@github-actions github-actions Bot added the pr-size: small Minimal code update label Sep 28, 2026
@github-actions

github-actions Bot commented Sep 28, 2026 •

Copy link
Copy Markdown

PR Performance Report

✅ No regression detected

No consistent slowdowns detected across all 2 environments.

0 IMPROVEMENTS 0 SLOWDOWNS 2/2 ENVIRONMENTS

Coverage: 2 of 2 environments completed. Advisory result; does not block merging.

Performance diagnostics

Phase times are inclusive diagnostics and must not be added together. They identify where measured time changed, not why it changed.

No affected phases or call-count changes were recorded.

All database tasks and timings

Unix / SQL Server 2022

Database task Before After Paired change Result
Connection opening 10.501 ms 10.795 ms +3.0% no signal
SELECT queries 1.072 ms 1.076 ms +0.3% no signal
Row insertion 34.154 ms 34.459 ms -0.2% no signal
Executemany inserts 160.583 ms 166.197 ms +3.5% no signal
Fetch-all queries 120.761 ms 122.773 ms +1.7% no signal
Row-by-row fetching 14.262 ms 14.604 ms +2.9% no signal
Batched row fetching 116.681 ms 117.631 ms +0.7% no signal
Transaction commit and rollback 114.445 ms 114.110 ms -1.1% no signal
Arrow row fetching 94.864 ms 94.472 ms +0.5% no signal
100,000-row insertion 439.152 ms 456.494 ms +4.2% no signal
Row fetching in batches of 100 119.948 ms 120.596 ms +1.2% no signal
Row fetching in batches of 10,000 134.876 ms 132.654 ms -1.6% no signal
Repeated positional queries 33.141 ms 33.682 ms +1.0% no signal
Repeated named-parameter queries 36.663 ms 36.309 ms +2.4% no signal
Legacy 100,000-row insertion 350.149 ms 358.906 ms +1.9% no signal
Insertion with explicit input sizes 491.480 ms 495.645 ms +2.6% no signal
Joined aggregation queries 177.214 ms 175.275 ms -1.7% no signal
Large joined-result fetching 189.986 ms 190.824 ms -0.8% no signal
1.2-million-row fetching 3490.661 ms 3459.806 ms -0.5% no signal
Common table expression queries 5.308 ms 5.340 ms +0.7% no signal
256 KiB VARCHAR(MAX) / fetchall() 1.289 ms 1.273 ms -3.1% no signal
10,000 scalar values / fetchval() (debug disabled) 115.978 ms 106.355 ms -8.9% no signal

Unix / SQL Server 2025

Database task Before After Paired change Result
Connection opening 97.409 ms 97.551 ms -0.6% no signal
SELECT queries 1.066 ms 1.069 ms -0.8% no signal
Row insertion 34.443 ms 34.707 ms +1.1% no signal
Executemany inserts 152.302 ms 155.473 ms +1.6% no signal
Fetch-all queries 123.504 ms 123.031 ms -0.6% no signal
Row-by-row fetching 14.821 ms 14.965 ms +0.2% no signal
Batched row fetching 118.239 ms 119.497 ms +0.9% no signal
Transaction commit and rollback 114.838 ms 114.204 ms -0.8% no signal
Arrow row fetching 94.240 ms 95.662 ms +4.2% no signal
100,000-row insertion 480.794 ms 470.948 ms -4.8% no signal
Row fetching in batches of 100 121.676 ms 122.965 ms +2.6% no signal
Row fetching in batches of 10,000 143.415 ms 141.933 ms -0.9% no signal
Repeated positional queries 33.439 ms 33.392 ms +0.6% no signal
Repeated named-parameter queries 36.281 ms 35.984 ms -1.0% no signal
Legacy 100,000-row insertion 359.022 ms 356.414 ms -1.1% no signal
Insertion with explicit input sizes 484.337 ms 495.181 ms +2.2% no signal
Joined aggregation queries 160.723 ms 159.775 ms -0.6% no signal
Large joined-result fetching 188.677 ms 189.115 ms -3.2% no signal
1.2-million-row fetching 3530.501 ms 3577.124 ms +2.0% no signal
Common table expression queries 5.186 ms 5.159 ms -0.5% no signal
256 KiB VARCHAR(MAX) / fetchall() 1.470 ms 1.483 ms +1.8% no signal
10,000 scalar values / fetchval() (debug disabled) 118.003 ms 108.225 ms -9.6% no signal
Build and measurement details

ADO build 179700

PR head: 39b880c4c7b383089493321d372c0ffd01f538c0
Base: c5831908977f0b8b355fda6f71d86629855d46aa
Measured merge: efbf4ce1c2f90fe707c99fe625b789d362e5db3a

  • Unix / SQL Server 2022: Python 3.12.3, x86_64, SQL 16.0.4295.3; 5 paired comparisons and 1 warmup.
  • Unix / SQL Server 2025: Python 3.12.3, x86_64, SQL 17.0.5005.3; 5 paired comparisons and 1 warmup.

A consistent change requires more than 20% median paired movement, at least 1 ms between the median runtimes, and at least 80% of pairs exceeding the relative threshold in the same direction. A slowdown without enough pair agreement is reported as inconsistent.

The displayed change is the median of paired before-and-after ratios. It is not recalculated from the two displayed median runtimes.

Both revisions use profiling-enabled builds on the same agent and database, with alternating order and discarded warmups. Results are diagnostic and do not represent production-wheel latency.

Raw samples and logs are attached to the ADO run as profiler-* artifacts.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🔵 Needs a closer look

Broader performance qualification and unresolved control results remain.

Review effort: Lite
Findings: None

What changed in this PR

This PR guards disabled debug logging in Cursor.fetchval() and strengthens related regression tests.

Changes:

  • Adds four per-call debug guards.
  • Expands tests for logging states, messages, and flag transitions.
  • Preserves fetch, result, EOF, and non-result behavior.
File Description
tests/​test_004_cursor.py Verifies fetchval logging and behavior.
mssql_python/​cursor.py Guards each fetchval debug call.

💡 Configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

@jahnvi480 Jahnvi Thakkar (jahnvi480) changed the title FIX: Guard disabled debug logging in fetchval only PERF: Guard disabled debug logging in fetchval only Sep 28, 2026
@github-actions

github-actions Bot commented Sep 28, 2026 •

Copy link
Copy Markdown

📊 Code Coverage Report

🔥 Diff Coverage

100%


🎯 Overall Coverage

84%


📈 Total Lines Covered: 9406 out of 11089
📁 Project: mssql-python


Diff Coverage

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

  • mssql_python/cursor.py (100%)

Summary

  • Total: 4 lines
  • Missing: 0 lines
  • Coverage: 100%

📋 Files Needing Attention

📉 Files with overall lowest coverage (click to expand)
mssql_python.pybind.performance_counter.hpp: 0.7%
mssql_python.pybind.logger_bridge.cpp: 57.9%
mssql_python.pybind.ddbc_bindings.h: 62.6%
mssql_python.pybind.logger_bridge.hpp: 70.8%
mssql_python.pybind.ddbc_bindings.cpp: 79.3%
mssql_python.pybind.connection.connection_pool.cpp: 82.3%
mssql_python.pybind.connection.connection.cpp: 83.1%
mssql_python.logging.py: 86.2%
mssql_python.pooling.py: 90.1%
mssql_python.pybind.fetch_temporal.hpp: 92.1%

🔗 Quick Links

⚙️ Build Summary 📋 Coverage Details

View Azure DevOps Build

Browse Full Coverage Report

Measure 10000 scalar fetches and EOF with debug logging disabled. Register one report workload, validate its timing and result contract, and keep existing production code and comparison thresholds unchanged.

Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
Copilot AI review requested due to automatic review settings September 28, 2026 12:12
@github-actions github-actions Bot added pr-size: medium Moderate update size and removed pr-size: small Minimal code update labels Sep 28, 2026

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🔵 Needs a closer look

Unresolved performance qualification and control results warrant final human review.

Review effort: Lite
Findings: None

Copilot AI lite review requested due to automatic review settings October 1, 2026 10:14

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🟡 Changes recommended

The profiler workload must be registered consistently across revisions so paired report validation succeeds.

Review effort: Lite
Findings: 1 High severity

Open (1)

)
result.update((name, (partial(query, sql=sql), False)) for name, sql in QUERIES.items())
result["lob_varchar_256k_fetchall"] = (lob_fetch, False)
result["scalar_fetchval"] = (scalar_fetchval, True)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

pr-size: medium Moderate update size

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants