From a3c21237ea55ea034aa0b7fc04edd01501b40741 Mon Sep 17 00:00:00 2001 From: Tam Nguyen Duc <1218621+tamnd@users.noreply.github.com> Date: Tue, 25 Aug 2026 08:17:48 +0700 Subject: [PATCH 1/2] Stop two tests failing for reasons that are not about this client Both have been red on main since the Rust 1.98 build change, which changed no code and is a coincidence of timing rather than a cause. The first is the appender against INSERT. It wants inserting to take more than five times what appending takes, which is the number that says the appender is still batching rather than doing a commit per row. It read three on a hosted runner and failed, and it fails on some jobs of a run and not others, which is what a threshold sitting in the middle of the measurement looks like. The row count was the problem. What an INSERT costs is what a commit costs, and that is a property of the disk rather than of the engine: 24 ms a row on a server with a real disk under contention, 80 us a row on a hosted runner where the commit is plainly not reaching a platter. Three hundred times apart from the same build. Two hundred rows is therefore four seconds of INSERT on the first machine and sixteen milliseconds on the second, and sixteen milliseconds is not enough work for the appender's one commit to have amortised, so the second machine was measuring what the appender costs to start rather than what it costs to run. So the row count is worked out on the machine instead of written down. Forty INSERTs say what one costs here, and the count is whatever spends about a second and a half on the INSERT side, floored at two hundred so the appender always has rows to amortise over and capped at forty thousand for memory. Measured on a real disk the ratio is 44 at two hundred rows, 81 at a thousand and 659 at five thousand, so the gate stays at five: the number that says the appender is batching, not the number any machine hits. The second is the test that counts how far the main thread gets while another one is inside the engine, which is how the released GIL is checked. It reads no clock, so it was not marked timing, so the sanitizer job runs it, and valgrind runs one thread at a time by design. The count is zero there whatever the binding does, and the test reports a held GIL that is not held. There is nothing to fix in the binding for that, so it takes the timing marker like the tests that read a clock, and the marker's description now covers both. --- pyproject.toml | 11 +++++- tests/test_appender.py | 79 +++++++++++++++++++++++++++++++----------- tests/test_threads.py | 9 +++++ 3 files changed, 78 insertions(+), 21 deletions(-) diff --git a/pyproject.toml b/pyproject.toml index 6d70b1e..f29dc2f 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -89,7 +89,16 @@ pythonpath = ["tools", "."] # slower by a factor nobody controls and the two sides of a ratio # slower by different ones. The jobs that run under one deselect them # by this marker and the ordinary jobs run them all. -markers = ["timing: asserts on elapsed time, so a sanitizer run has to skip it"] +# +# The marker covers one thing that reads no clock at all: counting how +# far the main thread gets while another one is inside the engine, which +# is how the GIL is checked to be released. Valgrind runs one thread at +# a time, so that count is zero there no matter what the binding does. +# It is the same problem for the same reason and it wants the same +# marker. +markers = [ + "timing: asserts on how fast or how concurrently something ran, so a sanitizer run has to skip it" +] [tool.ruff] target-version = "py311" diff --git a/tests/test_appender.py b/tests/test_appender.py index 87b5176..20db7a3 100644 --- a/tests/test_appender.py +++ b/tests/test_appender.py @@ -425,25 +425,55 @@ def run() -> None: assert ticks > 1000, f"the main thread only got {ticks} turns" -#: Rows for the comparison against `INSERT`, and few enough that the -#: `INSERT` half finishes in a few seconds. It is the slow half by three -#: orders of magnitude, and it gets slower as the table grows, because -#: every row of it is a commit and a fold. -COMPARED = 200 +#: What the `INSERT` half of the comparison is allowed to spend, and +#: the row count is worked out from it rather than written down. A fixed +#: row count cannot serve both kinds of machine this runs on, because +#: what an `INSERT` costs is what a commit costs and that is a property +#: of the disk and not of the engine. Measured per row: 24 ms on a +#: server with a real disk under contention, 80 us on a hosted CI runner +#: where a commit is not reaching a platter at all. Three hundred times +#: apart, from the same engine. Two hundred rows is four seconds on the +#: first and sixteen milliseconds on the second. +BUDGET = 1.5 + +#: How many `INSERT`s are timed to learn what one costs here. Enough to +#: average over, few enough to be quick on the slow machine, where this +#: alone is a second. +CALIBRATE = 40 + +#: The row count never goes outside this, whatever the calibration says. +#: The floor is where the appender has enough rows to have amortised the +#: one commit it does. The ceiling is memory and patience. +FEWEST = 200 +MOST = 40_000 + + +def _rows(count: int) -> list[tuple[int, str]]: + return [(uid, f"p{uid}") for uid in range(1, count)] + + +def _time_inserting(conn: zudb.Connection, rows: list[tuple[int, str]]) -> float: + started = time.perf_counter() + for uid, name in rows: + conn.execute("INSERT (p:person {uid: $u, name: $n})", {"u": uid, "n": name}) + return time.perf_counter() - started @pytest.mark.timing def test_appending_beats_inserting_by_the_margin_that_makes_it_worth_having( tmp_path: Path, ) -> None: - rows = [(uid, f"p{uid}") for uid in range(1, COMPARED)] + # What one INSERT costs here, asked rather than assumed. + with zudb.connect(tmp_path / "calibration.zu1") as conn: + conn.execute("INSERT (p:person {uid: 0, name: 'seed'})") + each = _time_inserting(conn, _rows(CALIBRATE)) / (CALIBRATE - 1) + + compared = min(MOST, max(FEWEST, int(BUDGET / each))) + rows = _rows(compared) with zudb.connect(tmp_path / "inserted.zu1") as conn: conn.execute("INSERT (p:person {uid: 0, name: 'seed'})") - started = time.perf_counter() - for uid, name in rows: - conn.execute("INSERT (p:person {uid: $u, name: $n})", {"u": uid, "n": name}) - inserting = time.perf_counter() - started + inserting = _time_inserting(conn, rows) with zudb.connect(tmp_path / "appended.zu1") as conn: conn.execute("INSERT (p:person {uid: 0, name: 'seed'})") @@ -451,15 +481,24 @@ def test_appending_beats_inserting_by_the_margin_that_makes_it_worth_having( with conn.appender("person") as app: app.append_rows(rows) appending = time.perf_counter() - started - assert conn.execute("MATCH (p:person) RETURN count(p) AS n").fetchone() == (COMPARED,) - - # Measured at about 150 times on this machine at this row count and - # rising with it, since one commit is one commit however many rows - # it carries. It is 18 on a shared CI runner, where a commit costs - # 25 ms of somebody else's disk and the appender's single one is - # most of what it spends, so the gate is 5: the number that says the - # appender is still batching rather than the number either machine - # hits. + assert conn.execute("MATCH (p:person) RETURN count(p) AS n").fetchone() == (compared,) + + # The appender does one commit however many rows it carries, so its + # cost is nearly all fixed and the ratio grows with the row count. + # That is the property being tested and it is why the row count is + # chosen instead of fixed: at two hundred rows on a machine where a + # commit is free, the appender is measured almost entirely on what + # it costs to start, the ratio sits around three, and it passes or + # fails on which way the runner was leaning that morning. It did + # both. Spending the same wall clock on the INSERT side everywhere + # puts enough rows on the appender for the answer to be about the + # engine. + # + # Measured at 44 with 200 rows, 81 with 1000 and 659 with 5000 on a + # server with a real disk. The gate is 5 because it is the number + # that says the appender is still batching, not the number any + # machine hits. assert inserting > 5 * appending, ( - f"{COMPARED} rows: {inserting * 1000:.0f} ms inserted, {appending * 1000:.0f} ms appended" + f"{compared} rows at {each * 1e6:.0f} us an INSERT: " + f"{inserting * 1000:.0f} ms inserted, {appending * 1000:.0f} ms appended" ) diff --git a/tests/test_threads.py b/tests/test_threads.py index 78964f7..2b88ba8 100644 --- a/tests/test_threads.py +++ b/tests/test_threads.py @@ -12,6 +12,7 @@ import threading from pathlib import Path +import pytest import zudb # Every pair of people, filtered, which is a statement that runs for @@ -62,6 +63,14 @@ def run() -> None: assert answers == [("ada",)] * 4 +# Marked timing not because it reads a clock but because it counts how +# far the main thread got while another one worked, and that number is +# only meaningful on a real scheduler. Valgrind runs one thread at a +# time by design, so the loop below gets zero turns there and the test +# reports a held GIL that is not held. There is nothing to fix in the +# binding for that, so the sanitizer run skips it the same way it skips +# the ones that read a clock. +@pytest.mark.timing def test_python_keeps_running_while_a_statement_does(crowd: zudb.Connection) -> None: ticks = 0 done = threading.Event() From ae8189ae96fa2aa141324ee319d1ecec14cafe84 Mon Sep 17 00:00:00 2001 From: Tam Nguyen Duc <1218621+tamnd@users.noreply.github.com> Date: Tue, 25 Aug 2026 11:32:28 +0700 Subject: [PATCH 2/2] Count turns of the loop rather than turns of the clock The third of the same kind, and the one that only shows on Windows. A task ticks while a stream waits for its next batch, and the test wants more than ten ticks to say the loop was free. It got nine. The tick loop yielded with asyncio.sleep(0.001). A millisecond is a millisecond on Linux and macOS and about fifteen on Windows, which is what that platform's timer resolves to, so the fifty milliseconds of waiting below bought three ticks there instead of fifty. The number being compared against ten was a property of the system clock and the test was passing on the two platforms whose clock happened to suit it. Yielding with no delay at all makes a tick one turn of the loop, which is what the test says it is about: a task reading rows off a scan leaves the loop free between batches and everything else on it keeps its turn. A held loop gives this task the gaps between batches, which is a handful of turns. A free one gives it thousands. Ten sits nowhere near either and no longer depends on how fast the machine is. --- tests/test_aio.py | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/tests/test_aio.py b/tests/test_aio.py index 567443b..7055b62 100644 --- a/tests/test_aio.py +++ b/tests/test_aio.py @@ -444,11 +444,18 @@ async def test_the_loop_runs_while_a_stream_waits_for_a_batch(tmp_path: Path) -> conn = await crowded(tmp_path / "free.zu1", LONG) ticks = 0 + # Yielding with no delay rather than with a small one, so that a + # tick is one turn of the loop and not one turn of the system + # clock. Asking for a millisecond gets a millisecond on Linux and + # macOS and about fifteen on Windows, which is what that platform's + # timer can resolve, and fifty milliseconds of waiting below then + # buys three ticks instead of fifty. This read 9 against a gate of + # 10 there and it was the clock it was measuring, not the loop. async def tick() -> None: nonlocal ticks while True: ticks += 1 - await asyncio.sleep(0.001) + await asyncio.sleep(0) async with conn: counting = asyncio.create_task(tick()) @@ -457,6 +464,10 @@ async def tick() -> None: await asyncio.sleep(0.05) counting.cancel() + # A loop held for the length of a batch would leave this task the + # gaps between batches, which is a handful of turns. A free one + # gives it thousands, so the gate is nowhere near either answer and + # does not care how fast the machine is. assert ticks > 10