Measure the claim, not the workflow around it - #164
Merged
Merged
Conversation
A run came back at 290 ms against a usual 30 and failed the ceiling I added yesterday. The ceiling was not the problem. The measurement was. The timed span started before `collectionExists`, a `deleteCollection`, a `createCollection` and an `upsert` with `wait = true`, and ended after the search. Five round trips, one of which blocks until a write is durable. So the number moved with the server's disk and the optimiser, and the README quoted it as how long a cold process takes to answer its first search. On a loaded runner that span can be 290 ms without anything in this repository being slower. The clock now covers what the sentence claims: process start, client construction, connecting, and one search against a collection the CI job seeded with curl before the binary ran. The write path still runs, past the clock, on its own collection, because those calls reach reflection the read path does not and an image proven only to read is not proven. The ceiling is 150 rather than 75, and the comment says why it is a guess: four samples told me the distribution was 29 to 42 and they were four samples of a narrower thing than I was measuring. It should be tightened when there are enough runs of the new span to know its shape. The README's comparison row drops the frozen figure. It says a cold process answers in tens of milliseconds, measured and bounded on every push, which is true without anyone editing it after a fast runner or a slow one.
|
This pull request adds no capability. The code it touches can already read the environment (2 places). What I could not follow1 call resolve to a name whose type is written nowhere, so what they reach is not established here. Across everything it read that is 1 of 51, 2%.
If one of those reaches the network or starts a process, this report does not show it. 3 files read · 2324 ms · against |
The first run of it reported 8 ms. 'Tens of milliseconds' was written before there was a measurement of the new span and describes the old one, which had a server creating a collection inside it. The table also now says why the figure fell, since a number dropping by 4x with no code change is the kind of thing a reader is right to distrust.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Fixes main, which I turned red in #163.
What actually went wrong
A run measured 290 ms against a usual 30 and failed the 75 ms ceiling I added yesterday. My first read
was that the ceiling was too tight. It was not: the measurement was measuring the wrong thing, and I had
put an assertion on it without reading what it covered.
The clock started here and stopped after the search:
Five round trips, one of them a durable write. That number moves with the server's disk and its
optimiser, and the README was quoting it as how long a cold process takes to answer its first search. On
a loaded shared runner it can be 290 ms with nothing here being slower.
What it measures now
Process start, client construction, connecting, one search. The collection is seeded by the job with
curl before the binary runs, because a collection the process created itself would be inside its own
measurement.
The write path still runs, past the clock, on a separate collection. Those calls reach reflection the
read path does not, and an image proven only to read is not proven, so losing that coverage to tighten a
number would have been a bad trade.
The ceiling
150 rather than 75, and the comment says it is provisional. I set 75 from four samples that turned out to
be four samples of a narrower thing than I was measuring. It should be tightened once there are enough
runs of the new span to know its shape, rather than from another handful.
The README
The comparison row no longer carries a frozen figure. It says a cold process answers in tens of
milliseconds, measured and bounded on every push, which stays true after a fast runner or a slow one
without anyone editing it. The paragraph under the table says what the timed span covers, since that is
the part that made the old number misleading rather than merely stale.