The test_invalid_json CI job spends 48 of its 51 minutes sleeping off rate limits

[adamtheturtle]

What happens

The ci-tests matrix in .github/workflows/test.yml has 104 ci_pattern entries. One of them dominates the whole workflow:

pattern	duration
test_invalid_json.py::TestInvalidJSON::test_invalid_json	51 min
test_vumark_generation_api.py	10 min
test_add_target.py::TestImage	9 min
61 of the remaining 101 patterns	under 2 min

The Test workflow is serialised on concurrency: vuforia_credentials, so this single job sets how long the shared lock is held: a run takes ~52 min, of which one job accounts for ~51.

What I checked

I pulled the log of that job from run 33862902163 and measured the gaps between consecutive test results:

tests:  71
span:   48.3 min
gaps > 5s:  55 gaps, totalling 48.2 min
gaps <= 5s: 0.1 min
gap sizes:  60s x33, 40s x12, 50s x4, 20s x2, 10s x2, 80s x1, 70s x1

Six seconds of that job is test work. Forty-eight minutes is sleeping.

The gaps are all multiples of ten seconds because of RETRY_ON_TRANSIENT_VWS_FAILURE in tests/mock_vws/utils/retries.py:

wait=wait_fixed(wait=10),
stop=stop_after_attempt(max_attempt_number=10),

handle_server_errors raises TooManyRequestsError on a 429, and each retry costs a flat ten seconds. A 60-second gap is six 429s in a row for one test.

The job is slow because it issues its requests as fast as it can — 71 real requests in about six seconds of actual work — and then waits out the rate limiter it just tripped. It is the worst offender because it is the widest cross-product in the suite: every content value x every endpoint x every backend.

Why it matters

The job is the critical path of a workflow which can only run one at a time, and holding the lock for ~52 minutes is what makes queued runs get evicted (GitHub allows only one pending run per concurrency group, so a third run is cancelled before it starts). Shortening this job shortens the lock and reduces how often that happens.

Suggested resolution

Split the pattern into the three cases the single test currently conflates, which are genuinely different inputs rather than an arbitrary shard:

• bytes which are not JSON at all (b"a")
• valid JSON which is not an object (b"[]", b'"hello"', b"5", b"null", b"true")
• a JSON object encoded as latin-1 rather than UTF-8

That is a 1 / 5 / 1 split, so the critical path becomes the five-value job at roughly 36 minutes, and a run drops from ~52 to ~37 minutes.

Two things to weigh before assuming that is the fix:

The gain depends on where Vuforia rate limits. Each matrix job gets its own credentials file and therefore its own database, so if the limit is per database, sharding really does divide the waiting. If it is per account, the 429s move rather than disappear and the total wait across the matrix is unchanged. I have not established which it is.

Sharding pushes credentialed jobs into the secrets wrap. There are only 100 credentials files, and the workflow already wraps with SECRET_INDEX=$((JOB_INDEX % 100)). Today indices 100-103 are test_healthcheck.py, test_docker.py, README.rst and docs/, which is benign because those barely touch real Vuforia. Adding two patterns pushes test_vumark_generation_api.py and test_vumark_generation_failure.py into the wrap, where they would share a database with the test_query.py jobs at indices 0 and 1. Whether that bites depends on runner scheduling — with 104 jobs and a much smaller concurrent-runner limit, index 0 has usually finished long before index 100 starts — but it is a hazard that grows with every pattern added, and the pool needs to grow past 100 or the tail needs to be reserved for patterns which do not use credentials.

The larger fix is probably not sharding at all. Six seconds of work should not take 48 minutes. Pacing the requests, or replacing wait_fixed(10) with an exponential backoff with jitter, would attack the cause rather than divide it across jobs. That is a change to shared retry behaviour with a much wider blast radius, so it is worth doing separately and deliberately.

[adamtheturtle]

Measured on run 33908079043, the first full matrix run with #3541 applied. All 111 jobs passed.

job	duration
test_not_an_object (5 bodies)	33.0 min
test_not_json (1 body)	6.3 min
test_not_utf_8 (1 body)	5.5 min
(was: test_invalid_json, 7 bodies)	51 min

Run wall time went from ~52 minutes to 34, and the critical path from 51 to 33.

What this says about the per-database question

The issue flagged that the gain depends on whether Vuforia rate limits per database or per account, and that I had not established which. The numbers now give a partial answer.

Purely linear scaling would put the five-body job at 51 x 5/7 = 36.4 minutes. It came in at 33.0, and the two single-body jobs at 6.3 and 5.5 rather than the ~7.3 a linear model predicts. So sharding is slightly better than linear, which is consistent with each shard tripping the limiter a little less often now that it issues fewer requests against its own database.

But only slightly. If the limit were purely per database and the shards were independent, three shards issuing a fifth to a seventh of the requests each should have collapsed to a few minutes, not 33. The cost is still dominated by waiting, and it still scales with the number of requests a single job makes.

So the framing in the "larger fix" section holds, and is if anything stronger. Sharding divides the waiting roughly in proportion to the split and no better. Getting this below ~30 minutes means attacking the 10-second wait_fixed or the request rate itself, not cutting the pattern into more pieces. A further split would buy proportionally less each time while adding jobs to a matrix that has already outgrown its 100 credentials files.

[adamtheturtle]

Closing this as resolved on main, with one correction to the diagnosis.

Where it stands

Latest full run on main (34135886145):

job	duration
test_not_an_object	2.3 min
test_not_json	0.7 min
test_not_utf_8	0.7 min
(was: test_invalid_json)	51 min

Two merged changes got it there:

• Split the test_invalid_json CI job into its three cases #3541 split the pattern into its three cases (51 → 33 min on the critical path).
• Harden real Vuforia tests against transient failures and exhausted allowance #3527 skips the Real Vuforia variants of test_not_json, test_not_an_object and test_not_utf_8 at collection time (pytest_collection_modifyitems in tests/mock_vws/fixtures/vuforia_backends.py), and cut _REQUEST_TIMEOUT_SECONDS from 30 to 5. The mock backends still verify the contract.

The critical path of a run is now test_vumark_generation_api.py at ~11 min, so this job no longer sets how long the vuforia_credentials lock is held.

The diagnosis was wrong about why it was slow

The original analysis attributed the 48 minutes to 429s being slept off ten seconds at a time. The job logs say otherwise:

• Pre-split job 100655483076 (47 min): 210 passed, zero retries. pytest-retry's "the following tests were retried" section is absent.
• Post-split test_not_an_object job 101137692727 (33 min): 150 passed, 1 retried. A single retry in a 33-minute job.

So no test was sleeping in retry_delay, and wait_fixed(10) in RETRY_ON_TRANSIENT_VWS_FAILURE was not involved. Real Vuforia simply takes 30 to 60 seconds to answer each malformed-body request and then returns the expected 400. The gaps were multiples of ten seconds by coincidence of Vuforia's own timing, not because of our retry interval. That is also why the split scaled almost exactly linearly: each request costs a fixed wait on the server side regardless of how many other requests the job has made.

This means the "larger fix" the issue proposed, replacing wait_fixed(10) with exponential backoff and jitter, would not have helped here and should not be done on the strength of this issue. The right fix was to stop sending those requests to the real service, which #3527 did.

Secrets wrap

The matrix is now 110 patterns against 100 credentials files. Indices 100 to 109 are test_vumark_generation_failure.py, test_target_validators.py, the four *_mock_usage.py files, test_flask_app_usage.py, test_healthcheck.py, test_docker.py, README.rst and docs/, none of which parametrise over the Real Vuforia backend. The ordering constraint is documented in the "Set secrets file" step of .github/workflows/test.yml. That stays a hazard for anyone adding a credentialed pattern, but it is not a problem today.