From 8f07b44dec511a2dcbd3dd14ba05d145b13d9762 Mon Sep 17 00:00:00 2001 From: Jahnvi Thakkar Date: Mon, 28 Sep 2026 16:00:38 +0530 Subject: [PATCH 1/2] FIX: Guard disabled debug logging in fetchval only 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> --- mssql_python/cursor.py | 12 ++++++---- tests/test_004_cursor.py | 47 +++++++++++++++++++++++++++++++++------- 2 files changed, 47 insertions(+), 12 deletions(-) diff --git a/mssql_python/cursor.py b/mssql_python/cursor.py index 0825ea1b..79436ab2 100644 --- a/mssql_python/cursor.py +++ b/mssql_python/cursor.py @@ -3847,23 +3847,27 @@ def fetchval(self): After calling fetchval(), the cursor position advances by one row, just like fetchone(). """ - logger.debug("fetchval: Fetching single value from first column") + if logger.is_debug_enabled: + logger.debug("fetchval: Fetching single value from first column") self._check_closed() # Check if the cursor is closed # Check if this is a result-producing statement if not self.description: # Non-result-set statement (INSERT, UPDATE, DELETE, etc.) - logger.debug("fetchval: No result set available (non-SELECT statement)") + if logger.is_debug_enabled: + logger.debug("fetchval: No result set available (non-SELECT statement)") return None # Fetch the first row row = self.fetchone() if row is None: - logger.debug("fetchval: No value available (no rows)") + if logger.is_debug_enabled: + logger.debug("fetchval: No value available (no rows)") return None - logger.debug("fetchval: Value retrieved successfully") + if logger.is_debug_enabled: + logger.debug("fetchval: Value retrieved successfully") return row[0] def commit(self): diff --git a/tests/test_004_cursor.py b/tests/test_004_cursor.py index f2050376..6900be7e 100644 --- a/tests/test_004_cursor.py +++ b/tests/test_004_cursor.py @@ -21,7 +21,7 @@ import mssql_python import uuid import re -from unittest.mock import patch +from unittest.mock import call, patch from conftest import is_azure_sql_connection # Setup test table @@ -5697,26 +5697,57 @@ def test_nextset_diagnostics(cursor, db_connection): def test_fetchval_basic_functionality(cursor, db_connection): - """Test basic fetchval functionality with simple queries""" - try: + """Test basic fetchval functionality and per-call debug logging guards.""" + with patch("mssql_python.cursor.logger") as mock_logger: + entry = call("fetchval: Fetching single value from first column") + debug = mock_logger.debug + mock_logger.is_debug_enabled = False # Test with COUNT query cursor.execute("SELECT COUNT(*) FROM sys.databases") + debug.reset_mock() count = cursor.fetchval() assert isinstance(count, int), "fetchval should return integer for COUNT(*)" assert count > 0, "COUNT(*) should return positive number" + assert cursor.fetchval() is None + debug.assert_not_called() # Test with literal value + mock_logger.is_debug_enabled = True cursor.execute("SELECT 42") + debug.reset_mock() value = cursor.fetchval() assert value == 42, "fetchval should return the literal value" + assert debug.call_args_list == [entry, call("fetchval: Value retrieved successfully")] + debug.reset_mock() + assert cursor.fetchval() is None + assert debug.call_args_list == [entry, call("fetchval: No value available (no rows)")] # Test with string literal cursor.execute("SELECT 'Hello World'") - text = cursor.fetchval() - assert text == "Hello World", "fetchval should return string literal" - - except Exception as e: - pytest.fail(f"Basic fetchval functionality test failed: {e}") + mock_logger.is_debug_enabled = False + debug.reset_mock() + fetchone = cursor.fetchone + + def fetchone_with_logging_change(): + row = fetchone() + mock_logger.is_debug_enabled = not mock_logger.is_debug_enabled + return row + + with patch.object(cursor, "fetchone", side_effect=fetchone_with_logging_change): + text = cursor.fetchval() + assert text == "Hello World", "fetchval should return string literal" + debug.assert_called_once_with("fetchval: Value retrieved successfully") + debug.reset_mock() + assert cursor.fetchval() is None + assert debug.call_args_list == [entry] + + cursor.execute("DECLARE @value int") + non_result = call("fetchval: No result set available (non-SELECT statement)") + for enabled in (False, True): + mock_logger.is_debug_enabled = enabled + debug.reset_mock() + assert cursor.fetchval() is None + assert debug.call_args_list == ([entry, non_result] if enabled else []) def test_fetchval_different_data_types(cursor, db_connection): From 0830faf539990a7478b4553411341ff378258508 Mon Sep 17 00:00:00 2001 From: Jahnvi Thakkar Date: Mon, 28 Sep 2026 17:42:30 +0530 Subject: [PATCH 2/2] PERF: Add scalar fetchval coverage to the PR performance 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> --- eng/profiler_benchmarks/README.md | 9 +++- eng/profiler_benchmarks/report.py | 1 + eng/profiler_benchmarks/workloads.py | 32 +++++++++++++ tests/test_036_profiler_ci.py | 72 +++++++++++++++++++++++++++- 4 files changed, 112 insertions(+), 2 deletions(-) diff --git a/eng/profiler_benchmarks/README.md b/eng/profiler_benchmarks/README.md index ef2365ad..2fdeb4d9 100644 --- a/eng/profiler_benchmarks/README.md +++ b/eng/profiler_benchmarks/README.md @@ -12,13 +12,20 @@ python -m eng.profiler_benchmarks.controller --base main --candidate HEAD \ python -m eng.profiler_benchmarks.report profiler-results/report.json ``` -The fixed registry has 21 tasks. `--scenarios` runs a local subset, but subset +The fixed registry has 22 tasks. `--scenarios` runs a local subset, but subset reports remain incomplete and cannot produce a verdict. `lob_varchar_256k_fetchall` fetches one 256 KiB `VARCHAR(MAX)` value to exercise multi-chunk streaming. Query setup and exact payload validation are outside the timed fetch window. +`scalar_fetchval` fetches 10,000 ordered, non-NULL integers from the existing test +table through `fetchval()`, followed by one EOF call. It requires debug logging to +be disabled without changing logger configuration. Query setup, exact-value/type +validation (including zero), EOF validation, and diagnostic checks are outside +the timed fetch window. Both revisions run the same workload; the report's +improvement thresholds are unchanged. + ## Measurement contract CI uses the PR merge's first parent as the exact base. It reuses the diff --git a/eng/profiler_benchmarks/report.py b/eng/profiler_benchmarks/report.py index 6ac2723f..07f176f1 100644 --- a/eng/profiler_benchmarks/report.py +++ b/eng/profiler_benchmarks/report.py @@ -38,6 +38,7 @@ "fetch_1_2m": "1.2-million-row fetching", "cte": "Common table expression queries", "lob_varchar_256k_fetchall": "256 KiB VARCHAR(MAX) / fetchall()", + "scalar_fetchval": "10,000 scalar values / fetchval() (debug disabled)", } CASES = tuple(TASK_NAMES) MAX_BYTES = 8 * 1024 * 1024 diff --git a/eng/profiler_benchmarks/workloads.py b/eng/profiler_benchmarks/workloads.py index c183f5d8..9059ab6c 100644 --- a/eng/profiler_benchmarks/workloads.py +++ b/eng/profiler_benchmarks/workloads.py @@ -163,6 +163,37 @@ def lob_fetch(conn, ctx): ctx.disable() +def scalar_fetchval(conn, table, ctx): + """Measure scalar fetching with debug disabled, excluding setup and validation.""" + from mssql_python.logging import logger + + if logger.is_debug_enabled: + raise ValueError("scalar_fetchval requires debug logging to be disabled") + + expected = list(range(10_000)) + with conn.cursor() as cursor: + cursor.execute(f"SELECT TOP (10000) int_col FROM {table} ORDER BY id") + ctx.enable() + try: + start = time.perf_counter() + values = [cursor.fetchval() for _ in expected] + eof = cursor.fetchval() + wall_ms = (time.perf_counter() - start) * 1000 + cpp, py = ctx.collect() + assert values == expected and all(type(value) is int for value in values) + assert eof is None, "Scalar fetch did not reach EOF" + assert not cursor.messages, "Clean scalar fetch unexpectedly produced diagnostics" + return dict( + title="Scalar fetchval", + wall_ms=wall_ms, + cpp=cpp, + py=py, + detail="Rows: 10000; type: int; API: fetchval; debug: disabled", + ) + finally: + ctx.disable() + + def registry(): """Keep every PR #552 scenario, including its existing timing boundaries.""" result = dict(scenarios.SCENARIOS) @@ -176,4 +207,5 @@ def registry(): ) 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) return result diff --git a/tests/test_036_profiler_ci.py b/tests/test_036_profiler_ci.py index eced790d..8f5e24ee 100644 --- a/tests/test_036_profiler_ci.py +++ b/tests/test_036_profiler_ci.py @@ -687,12 +687,82 @@ def __exit__(self, *args): def test_report_cases_match_the_executed_workload_registry(): _, workloads = controller.load_suite() assert tuple(workloads.registry()) == reporting.CASES - assert len(reporting.CASES) == 21 + assert len(reporting.CASES) == 22 + assert workloads.registry()["scalar_fetchval"] == (workloads.scalar_fetchval, True) assert [name for name in reporting.CASES if name.startswith("lob_")] == [ "lob_varchar_256k_fetchall", ] +def test_scalar_fetchval_workload_times_only_fetch_and_reaches_eof(monkeypatch, report): + monkeypatch.setattr("mssql_python.logging.logger", SimpleNamespace(is_debug_enabled=False)) + cursor = MagicMock() + cursor.fetchval.side_effect = [*range(10_000), None] + cursor.messages = [] + connection = MagicMock() + connection.cursor.return_value.__enter__.return_value = cursor + context = MagicMock() + context.collect.return_value = ({}, {}) + + def clock(): + cursor.execute.assert_called_once_with( + "SELECT TOP (10000) int_col FROM #perf_test ORDER BY id" + ) + context.enable.assert_called_once() + context.collect.assert_not_called() + assert cursor.fetchval.call_count in (0, 10_001) + return 1.1 if cursor.fetchval.call_count else 1.0 + + monkeypatch.setattr(benchmark_workloads.time, "perf_counter", clock) + result = benchmark_workloads.scalar_fetchval(connection, "#perf_test", context) + assert result["wall_ms"] == pytest.approx(100) + assert result["detail"] == "Rows: 10000; type: int; API: fetchval; debug: disabled" + assert cursor.fetchval.call_count == 10_001 + cursor.fetchone.assert_not_called() + cursor.fetchall.assert_not_called() + cursor.fetchmany.assert_not_called() + context.collect.assert_called_once() + context.disable.assert_called_once() + connection.cursor.return_value.__exit__.assert_called_once() + assert reporting.TASK_NAMES["scalar_fetchval"] in reporting.render([report], "c" * 40, 42) + + +@pytest.mark.parametrize( + "problem", ("wrong-value", "wrong-type", "missing", "extra", "warning", "error", "debug") +) +def test_scalar_fetchval_workload_rejects_invalid_measurements(monkeypatch, problem): + monkeypatch.setattr( + "mssql_python.logging.logger", SimpleNamespace(is_debug_enabled=problem == "debug") + ) + values = [*range(10_000), None] + cursor = MagicMock() + cursor.messages = [] + if problem == "wrong-value": + values[0] = -1 + elif problem == "wrong-type": + values[0] = 0.0 + elif problem == "missing": + values[0] = None + elif problem == "extra": + values[-1] = 10_000 + elif problem == "warning": + cursor.messages = [("01000", "unexpected")] + cursor.fetchval.side_effect = RuntimeError("fetch failed") if problem == "error" else values + connection = MagicMock() + connection.cursor.return_value.__enter__.return_value = cursor + context = MagicMock() + context.collect.return_value = ({}, {}) + error = {"debug": ValueError, "error": RuntimeError}.get(problem, AssertionError) + with pytest.raises(error): + benchmark_workloads.scalar_fetchval(connection, "#perf_test", context) + if problem == "debug": + connection.cursor.assert_not_called() + context.enable.assert_not_called() + else: + context.disable.assert_called_once() + connection.cursor.return_value.__exit__.assert_called_once() + + def test_lob_workload_validates_payload_and_times_only_fetch(monkeypatch): size = 256 * 1024 expected = "x" * size