PERF: Guard disabled debug logging in fetchval only

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

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

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

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):

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):

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