diff --git a/eng/profiler_benchmarks/README.md b/eng/profiler_benchmarks/README.md index ef2365adf..2fdeb4d91 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 6ac2723f2..07f176f18 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 c183f5d89..9059ab6c9 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/mssql_python/cursor.py b/mssql_python/cursor.py index 0825ea1b5..79436ab2e 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 f2050376f..6900be7ea 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): diff --git a/tests/test_036_profiler_ci.py b/tests/test_036_profiler_ci.py index eced790d5..8f5e24eed 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