test: cut the integration suite from 101s to 15s - #101
Merged
Merged
Conversation
Two thirds of the run was bcrypt. Every authenticated request verifies the seeded client's secret, and at cost 12 that is ~180ms of CPU on a single uvicorn worker. The seeded hash is now cost 4; the cost travels inside the hash, so nothing outside this fixture changes, and clients created through the API still get 12. 101s -> 35s. That exposed a collision the slow requests had been hiding. The DOI mock built its identifier from the current time to the second, so two tests creating a DOI in the same second got 409 doi_already_exists. The suffix is now random, generated once per response so id, doi and suffix agree. ALPHANUMERIC_UPPER, used by the other mock bodies, is not a WireMock type and silently produced symbols; this uses ALPHANUMERIC with uppercase=true. Most of what remained was 21 fixed one-second sleeps before reading the container log. tests/integration/utils/container_log.py replaces them: wait_for_log polls until the expected line is there, and flush_log makes a marker request and waits for it, so an assertion that something was NOT logged runs only once everything before it has been written. The degradation test now matches the line of its own request rather than any line from the last minute, which the previous test's outage could also satisfy. 233 pass on a clean stack, four runs, 14.5-15.6s. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Start services spent 47-71s, most of it compiling dependencies on alpine in the builder stage. Compose only builds an image it cannot find, so building it first with the gha cache makes `up` reuse it, and the builder stage is rebuilt only when requirements.txt changes. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Timestamps on pytest's progress lines mark when a file finishes, not when it starts, which pointed the last investigation at the wrong file. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
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
1 participant
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.
🤔 Problem
The CI takes ~5 min, and almost all of it is the
integrationjob: ~3m15s running the tests and 47–71s starting services. Theunitjob takes ~30s.🧐 Solution
checkpw. This alone took the suite from 101s to 35s locally.nowat one-second resolution. With fast requests, two tests collided with409 doi_already_exists. This bug was being hidden by the slowness.time.sleep(1)in the log tests, via the newtests/integration/utils/container_log.py:wait_for_logfor "was logged" assertions;flush_log(a marker request) for "was not logged" assertions.type=gha) for the image build in the integration job.🤨 Rationale
--durations=0). The time was not in the tests themselves, so concurrency (xdist) would have attacked the wrong thing. It would also be risky here:object_storage_downstops MinIO for everyone, and the log tests read a shareddocker logs.flush_logstill catch leaks: in 20/20 attempts, a line written just before the barrier was already in the log.Locally: 233 passed on a clean stack, 4 runs, 14.5–15.6s (baseline 101s). The CI time is still to be confirmed by this run; the build cache only takes effect from the second run.
Side finding, not addressed here:
authenticateisasync defand calls bcrypt synchronously. It blocks the event loop for ~180ms per request in production too. With 10 concurrent requests, even the health-check waited 1.7s.🤖 Generated with Claude Code