Stop three tests failing for reasons that are not about this client - #39
Conversation
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.
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.
tamnd
changed the title
|
A third one, found by this branch turning the first two green and The tick task yielded with It now yields with no delay, so a tick is one turn of the loop, which All three are the same defect wearing different clothes: an assertion The whole of test_aio.py passes on a Linux host, 34 tests. |
1 participant
Main has been red since #36, which changes no code at all: it moves the
Rust toolchain from 1.97.1 to 1.98.0. Neither of the two tests behind
the red is finding a defect, and the toolchain bump is when they
started failing rather than why.
The appender is measured against
INSERTand the gate is thatinserting takes more than five times what appending takes, which is the
number that says the appender is still batching rather than committing
per row. It read three on a hosted runner. My first guess was runner
noise and it was wrong: measuring the fastest of three runs on each
side returned the same numbers, 16 ms inserted against 5 ms appended.
It reproduces.
The row count is what is wrong. An
INSERTcosts what a commit costs,and that is a property of the disk and not of the engine. Measured per
row from the same build:
Three hundred times apart. Two hundred rows is four seconds of
INSERTon the first machine and sixteen milliseconds on the second, and
sixteen milliseconds is not enough work for the appender's single
commit to have amortised against. On the runner the test was measuring
what the appender costs to start, not what it costs to run, which is
why it sat near the threshold and fell on either side of it depending
on the job. In the last red run both ubuntu jobs and both windows jobs
failed; in the one before, one ubuntu job failed and the other passed.
So the row count is now worked out on the machine rather than written
down. Forty
INSERTs say what one costs here, and the count iswhatever spends about a second and a half on the
INSERTside, flooredat two hundred so the appender always has rows to amortise over and
capped at forty thousand for memory. That is roughly two hundred rows
on the slow machine and around eighteen thousand on the fast one, and
about the same wall clock on both.
The ratio on a real disk is 44 at two hundred rows, 81 at a thousand
and 659 at five thousand, which is the shape you would expect from one
commit however many rows it carries. The gate stays at five for the
same reason it was five before: it is the number that says the appender
is batching, not the number any machine hits.
The other test is
test_python_keeps_running_while_a_statement_does,which counts how far the main thread gets while another one is inside
the engine. That is how a released GIL is checked and it is worth
checking. It reads no clock, so it was not marked
timing, so theleaksjob runs it under valgrind, which runs one thread at a time bydesign. The count is zero there no matter what the binding does. It now
takes the
timingmarker, which is what theleaksjob deselects by,and the marker's description in pyproject.toml covers both cases: it is
about asserting on how fast or how concurrently something ran, and both
of those need a real machine.
The
apijob's red ona8a8330is a third thing and is not fixed herebecause it does not need fixing.
Valuegainedbytesin #38 andgriffe reports a widened union as a changed attribute value, compared
against
HEAD^. The baseline moves with the next push, so it is greenfrom here. It will fire again the next time
Valuegrows, and the onlyescape the job has is a version bump that turns the whole check off for
that push, so that is #40 rather than something to reach for now.
Verified on a Linux host: the whole of test_appender.py passes,
including this one.