From 3f3c46566348d9e93154a5d0c596523537c42bc6 Mon Sep 17 00:00:00 2001 From: S'Bussiso Dube <80188685+Sbussiso@users.noreply.github.com> Date: Sun, 13 Sep 2026 21:27:31 -0700 Subject: [PATCH] Measure the schema bring-up, and record why it can't just be backgrounded MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review pass two flagged that create_all() and sync_schema() run synchronously at module import while sync_indexes was deliberately moved out of that path, and recommended moving both behind the same background step. Having now measured it, that recommendation was wrong twice over, and this commit records why so nobody spends the afternoon I just did. FIRST: relocating to lifespan would change nothing. uvicorn runs lifespan startup BEFORE it binds the socket — measured 2026-09-13 with a 6s artificial startup delay, TCP connections were refused for the whole of it and accepted only after. Module import is earlier still, so both positions are equally invisible to a health check. What actually makes sync_indexes safe is not its location: it is asyncio.create_task(asyncio.to_thread(...)), fire-and-forget, so startup returns immediately and the port binds while indexes build. SECOND: backgrounding these two is not safe. Indexes only make queries faster, so building them late is invisible. create_all and sync_schema make queries *possible* — background the first and a fresh database serves its first request against missing tables; background the second and every query touching a newly added column errors until it lands. That trades a noisy deploy failure for a silent data-error storm. So the original finding was right about the hazard (nothing is listening while this runs, Fly's grace is 30s, and the single-machine `immediate` strategy means failing it takes out the only machine) and wrong about the remedy. The lever actually available is visibility. Both calls are now timed and logged, with a WARNING above 10s of the 30s budget that names the consequence, because "machine never became healthy" looks nothing like "a migration got slow". Verified both branches fire: INFO at 0.02s on a normal boot, WARNING with the threshold lowered. 874 backend tests pass, ruff clean. Co-Authored-By: Claude Opus 5 --- backend/app/main.py | 50 ++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 49 insertions(+), 1 deletion(-) diff --git a/backend/app/main.py b/backend/app/main.py index 5ebd16e..33272de 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -73,10 +73,58 @@ traces_sample_rate=settings.SENTRY_TRACES_SAMPLE_RATE, ) +# Schema bring-up. Both calls stay SYNCHRONOUS and stay HERE, deliberately — +# see the note below before moving them. +# +# THE BOOT BUDGET: nothing is listening on the port while this runs. Measured +# 2026-09-13: uvicorn runs lifespan startup BEFORE it binds, so a connection +# is refused for the whole of startup — and module import, where this code +# lives, is earlier still. Fly's http check for the `app` group allows a 30s +# grace_period, and on the single-machine `immediate` deploy strategy +# exceeding it fails the only machine with nothing serving. +# +# WHY NOT BACKGROUND THEM like sync_indexes below: indexes only make queries +# faster, so building them late is invisible. These two make queries +# *possible*. Backgrounding create_all means the first request on a fresh +# database hits missing tables, and backgrounding sync_schema means every +# query touching a newly added column errors until it lands — trading a +# noisy deploy failure for a silent data-error storm, which is worse. +# +# WHY NOT MOVE THEM INTO lifespan: measured, it changes nothing. The port is +# unbound during lifespan startup too. The thing that makes sync_indexes safe +# is not its location, it is that it is fire-and-forget in a worker thread. +# +# So the lever that is actually available is visibility: time them, and say +# so loudly when they start eating the budget, because the failure they +# produce (machine never becomes healthy) looks nothing like its cause. +_ddl_started = time.perf_counter() Base.metadata.create_all(bind=engine) +_create_all_seconds = time.perf_counter() - _ddl_started + # Patch in any columns that were added to existing models after the table was first # created. See app/core/migrations.py for the "why" — this is our stand-in for Alembic. -sync_schema(engine, Base.metadata) +_sync_started = time.perf_counter() +_schema_changes = sync_schema(engine, Base.metadata) +_sync_schema_seconds = time.perf_counter() - _sync_started +_ddl_seconds = _create_all_seconds + _sync_schema_seconds + +# 10s of a 30s grace, with Python imports and Sentry init still to pay for. +_DDL_BUDGET_WARN_SECONDS = 10.0 +if _ddl_seconds >= _DDL_BUDGET_WARN_SECONDS: + logging.getLogger(__name__).warning( + "Schema bring-up took %.1fs (create_all %.1fs, sync_schema %.1fs, " + "changes: %s). Nothing is listening on the port until this finishes " + "and Fly's health grace is 30s — a slower migration than this will " + "fail the deploy rather than run late.", + _ddl_seconds, _create_all_seconds, _sync_schema_seconds, + ", ".join(_schema_changes) or "none", + ) +else: + logging.getLogger(__name__).info( + "Schema bring-up %.2fs (create_all %.2fs, sync_schema %.2fs, changes: %s)", + _ddl_seconds, _create_all_seconds, _sync_schema_seconds, + ", ".join(_schema_changes) or "none", + ) # Indexes declared on models AFTER their table first shipped never get # created by create_all (it skips existing tables entirely) — several # hot-path composites were missing in prod because of this. See