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_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 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()