From 60 seconds to under 4: a two-day WAL migration, live in prod.

The moment we knew

On 2026-07-04 at 07:47Z we fired a 50-user load test against production. Fifty concurrent clients, five spawn per second, five-minute steady window, one endpoint: POST /v1/events. The kind of profile any real customer's SDK would produce on a modest campaign send.

The result came back with a p99 of 60 seconds. That is not a real number. That is our load generator's timeout ceiling. The real p99 was somewhere north of a minute, and we were measuring the wall we hit before we could measure it. Throughput was 2.11 rps. Success rate 93%. The rest were HTTP 504s from the Cloudflare edge.

Forty-eight hours later, on 2026-07-06 at 05:10Z, we cut the global INGESTION_MODE=wal flip in production. Between those two timestamps we shipped a 7-decision performance fix (ADR-0011), an in-memory batched counter (ADR-0012), a full write-ahead-log producer (Phase 12), a full WAL consumer stack (Phase 13), and a same-day canary that pushed 20,008 events end-to-end at 100% parity. We also found eight real bugs that had been silently broken in production for months.

This is the log. What we ran, what broke, what we learned.

Baseline: what 60 seconds looks like

The pre-optimization run against synapse-api.pyrx.tech:

The failure mode was head-of-line blocking on synchronous bcrypt inside an async FastAPI dependency. Two uvicorn workers on a 2-CPU VM, and every request path did bcrypt verification on the event loop. At 50 clients that meant every request queued behind the two workers' bcrypt CPU time. Napkin math: 50 users × 250ms bcrypt / 2 workers = 6.25 seconds of head-of-line blocking per request, just for auth. That alone explains the p99 spread.

The Cloudflare 504s were what the client saw. The p99 above 60 seconds was what we couldn't quite see because our load harness gave up first.

Day one: seven decisions, canary-gated

ADR-0011 broke the fix into a stack. We shipped them one at a time, canaried each against prod, and refused to bundle. Bundling would have made attribution impossible.

D2 (Redis-cached api-key resolution) + D5 (per-endpoint latency histograms). PR #245, commit cdba8678. Cache the workspace-id + api-key lookup with a 30-second positive TTL and a 5-second negative TTL. On the miss path, fall through to the DB and bcrypt exactly as before; on the hit path, one Redis GET. Curl probes confirmed the mechanism: 297 ms cold, 0.5–1.2 ms hot. The canary went from 2.11 rps / 60 s p99 to 4.72 rps / 40 s p99.

Then something more interesting happened. Along with the throughput improvement came a new failure mode we had never seen before: 79 asyncpg.exceptions.DeadlockDetectedError in a 5-minute window.

DETAIL: Process 696962 waits for ShareLock on transaction 12871; blocked by process 696959.
        Process 696959 waits for ShareLock on transaction 12874; blocked by process 696962.

This is a lesson worth writing down. Removing a serialization point can uncover contention that was hidden by throughput throttling. Pre-D2, bcrypt was serializing the entire event-ingest pipeline at 2 rps. Any two requests that would deadlock at the DB layer almost never actually reached the DB at the same time — they queued behind bcrypt. Once we removed that queue, 50 concurrent users finally reached the write path together. The row-lock geometry that was latent under low concurrency became the dominant failure.

We traced the cycle to four hot rows the ingest transaction wrote in this order:

1. UPDATE api_keys SET last_used_at, last_used_ip — one shared row per key
2. UPDATE contacts — usually unique per user
3. INSERT INTO events — unique per row
4. UPDATE tenants SET monthly_events_used = monthly_events_used + 1 — one shared row per tenant

Row 4 was the smoking gun. It is the only single-row write that every event ingest under load must contest. Two transactions each holding one hot row and waiting on the other's transaction id: cycle formed, deadlock detected.

D6. PR #246, 46340dcb. Move the counter increment out of the request-path transaction. Fire-and-forget on a fresh session via asyncio.create_task, structured logging on failure, no exception propagation to the caller. The counter update becomes a single-row UPDATE in its own micro-transaction — Postgres serializes concurrent single-row UPDATEs against the same tenant row, but that serialization cannot deadlock.

The next canary: throughput 16.5 rps, p50 966 ms, p99 29 s, deadlocks in the 5-min window: 0.

Then the remaining ADR-0011 stack:

• D4 (fire-and-forget Celery publishes). PR #247. Wrap celery.delay() in asyncio.create_task(asyncio.to_thread(...)) so the AMQP publish stops blocking the event loop for the RabbitMQ round-trip.
• D1 (bcrypt off the loop). PR #249. asyncio.to_thread(bcrypt.checkpw, ...) on the cache-miss path.
• D3 (uvicorn workers 2 → 4). PR #251. Server-side 4xx p99 dropped from 21,000 ms to 967 ms — a −95% move that confirmed the pre-ingest chain had been worker-starved.
• D7 (Pub/Sub no-op on Celery deployments). PR #250. This is where the story turns strange. See below.

Best warm-cache result on the direct path after this stack: 35 rps at p99 = 3,645 ms. From 60 seconds to 3.6 seconds on the same endpoint on the same VM.

Then we hit the residual tail. Task #99 instrumentation (PRs #252, #253) proved that with ingest_event and pool acquisition and session commit all summing to ~4.2 s of known server-side work, the client-side p99 was still 12 s. Eight seconds of unexplained gap. Which turned out to be asyncio scheduling overhead: 4 workers × 12 concurrent coroutines per worker × several await points per request equals a lot of queuing at every yield.

ADR-0012. PR #254. Replace D6's per-request asyncio.create_task with a per-worker in-memory dict[uuid.UUID, int] buffer under an asyncio lock, flushed every 5 seconds by a single background loop that issues one UPDATE tenants per unique tenant. On the hot path, incrementing a tenant's counter is now a synchronous dict mutation — nanoseconds, zero I/O, zero await. Canary #13 confirmed: ingest_event p99 went from 2,129 ms to 939 ms, a further −56%.

Day two: the write-ahead log

The direct-path fix stack had done what it could. To go further we needed a structural change. Phase 12 was the write-ahead log producer: POST /v1/events publishes a versioned envelope to a Pub/Sub topic, returns 202 Accepted, and downstream consumers own the DB write.

The Phase 12 shadow-mode canary was where we found our first surprise.

The bugs that only surface at production scale

1. GCP_PROJECT_ID="CHANGE_ME"

We flipped INGESTION_MODE=shadow + WAL_DRIVER=pubsub on the load-test workspace and fired the canary. The validation script reported PASS. So did the producer-active gauge. Everything looked fine.

Everything was not fine. 100% of the shadow-mode WAL publishes were failing with InvalidArgument from Google Pub/Sub. The producer was building the topic path as projects/CHANGE_ME/topics/synapse-events.normal — because GCP_PROJECT_ID in /opt/pyrx/deploy/.env on the prod VM was still the template placeholder from whenever that .env was first provisioned.

This bug had been silently broken for months. Every Pub/Sub publish since that .env file existed had been failing against a placeholder project id. The error was hidden because the publisher's callback logged pubsub_publish_failed in the background, and nothing was paging on it.

This also explained ADR-0011 D7. Recall D7: PR #250 silenced 1,565 pubsub_publish_failed errors per 5 minutes by making the raw-event Pub/Sub stream a no-op on Celery deployments. We thought we were silencing dead code. We were actually silencing a broken configuration — the log volume was correct, the project id was wrong, and D7 had made the symptom invisible while leaving the underlying config bug in place.

The Phase 12 canary was the thing that surfaced it. You cannot find CHANGE_ME in a code review because it's not in the code. You find it when the code tries to use it.

Fix: GCP_PROJECT_ID=cep-mvp-prod, redeploy, smoke test confirms.

2. VM default SA missing publisher IAM

Same canary run. Even after fixing GCP_PROJECT_ID, publishes still failed. The VM's default compute service account (<vm-default-compute-sa>) lacked roles/pubsub.publisher on the four priority topics. The dedicated events SA did have the role, but it wasn't wired to the container — the container was using Application Default Credentials via VM metadata, which resolves to the default compute SA.

Fix: gcloud pubsub topics add-iam-policy-binding on all four priority topics + the DLQ. Follow-up filed to either narrow the default SA's scope or mount the dedicated SA.

3. Validation gap: shadow-mode success rate

Our canary validation script (validate_wal_canary.py, 492 lines) checked deltas on wal_publish_total. In shadow mode, the WAL path fires through shadow_mode.execute_shadow, which records to a different counter (shadow_publish_total, labelled with direct_status and wal_status). The wal_publish_success_rate check silently skipped because wal_publish_total did not move.

Which is how Step 3 of the Phase 12 runbook could report PASS while 100% of WAL publishes were failing. The only reason we caught it was that the latency-delta check kept firing (it measures wall-clock time regardless of success) and the producer-active gauge flatlined at 1.

Follow-up filed as task #112.

4. Runbook awk | tee | mv truncated the prod .env

The Step 2 .env rewrite in the Phase 12 runbook piped through sudo tee "$tmpfile" followed by sudo mv "$tmpfile" "$ENV_FILE". On the first attempt tee failed with permission denied, but the subsequent mv still executed, moving an empty tmpfile over .env and truncating it from 3,417 bytes to 2 lines. The next deploy died with AUTH_ADMIN_API_KEY missing. Recovered from the pre-canary backup and rewrote the runbook to use an idempotent append pattern.

5. topic_name() dropped the prefix

Day two, Phase 13, executing the consumer canary. The consumer code went to subscribe to events.high-persister. There is no such subscription. There is synapse-events.high-persister, because Phase 12's producer + Makefile provisioning both use settings.wal_topic_prefix, which defaults to synapse-events. But wal/base.py:37's topic_name() had a hardcoded events. prefix from an earlier draft. Consumer boot, subscription-not-found, crash loop.

# Before (broken):
def topic_name(priority: Priority) -> str:
    return f"events.{priority.value}"

# After (PR #274):
def topic_name(priority: Priority) -> str:
    from app.core.config import settings
    return f"{settings.wal_topic_prefix}.{priority.value}"

(PR #274.)

6. _pull_blocking did not catch DeadlineExceeded

Also day two. The PubSubConsumer._pull_blocking docstring said pull returns an empty list when the deadline elapses. The docstring was wrong. The sync gRPC client.pull(timeout=...) raises google.api_core.exceptions.DeadlineExceeded on empty subscriptions. Every idle subscription — which is every subscription in wal-off state — crashed the pull loop.

Unit tests missed this because they mocked at a higher layer than the gRPC client. The behavior only surfaces against the real Pub/Sub SDK.

# After (PR #275):
try:
    response = client.pull(
        request={"subscription": self._subscription_path, "max_messages": max_messages},
        timeout=timeout_s,
    )
except gcp_exceptions.DeadlineExceeded:
    return []

(PR #275.)

7. Persister envelope schema mismatch

This one was the closest call. The producer's WALEnvelope puts event_id and user_id at the top level of the envelope and does not pre-resolve a contact — contact upsert is the persister's job on the consumer path, mirroring what ingest_event does on the direct path. The persister was reading payload.event_id and payload.contact_id. Neither exists on a real envelope. Every WAL-mode event was being acked and silently dropped with event_missing_required_fields.

100% of pre-fix events were being logged as invalid and thrown away. The persister's own logs said everything was fine. The events table said otherwise.

# After (PR #276) — persister does the contact upsert itself,
# using the same service call the direct path uses:
env = msg.envelope
external_id = env.user_id
event_name = env.event_name

upserted = await contact_service.upsert_contact(
    tenant_id=tenant_id,
    external_id=external_id,
    ...
)
event_row = Event(
    id=_envelope_id_to_row_uuid(env.event_id),
    contact_id=upserted.id,
    ...
)

(PR #276.) Producer publishes what it always published. Consumer now reads what the envelope actually is.

8. Docker image staleness

Not a code bug — a workflow gap that felt like one. Consumer redeploys via docker compose up -d --force-recreate consumer-persister reuse the existing synapse-api:latest image. That means a Phase 13 hotfix (say, PR #276) requires a full make deploy-api to rebuild the image before consumers can pick it up. We chased a "why isn't my fix live" ghost for a few minutes before spotting this. Documented in the runbook for Step 2b.

What we shipped: the receipts

Global INGESTION_MODE=wal executed at 05:10Z on 2026-07-06. Between 04:45 and 05:22 we ran two 10-minute canaries — one per-tenant via a Redis override, one on the global flag — with the WAL driver flip in between. Then a compressed 2-hour soak on synthetic traffic.

Two-hour soak checkpoints at T+10, T+30, T+60, T+90, T+120 minutes:

• consumer-persister memory drift over 90 minutes between T+30 and T+120: +0.5 MiB, out of a 512 MiB limit. Well inside allocator noise.
• consumer-flow-trigger memory drift over the same window: +0.7 MiB.
• CPU steady at sub-1% throughout on both consumers.
• End-to-end parity: 100% at every checkpoint.

Compared to the pre-D2 baseline observed at session start:

51× on throughput is a specific measurement: POST /v1/events, one endpoint, on a cpus: "2" compose limit, from an operator laptop with 50 concurrent threads. It is not a claim about any other endpoint, any other VM, or any other client shape. The number is real, and we would like to be honest about which number it is.

What we accepted, and what we did not verify

Some things this migration explicitly did not accomplish.

No customer-visible product feature shipped. These 48 hours were entirely infrastructure. If you were using Synapse before 2026-07-04, the API contract you consumed is unchanged. The perceived difference is that HTTP 202 comes back a lot faster.

We hit ProduceTimeoutError twice. Both at exactly latency_ms=2001.xxx on synapse-events.normal, both around T+60 in the soak, both immediately followed by successful sub-100ms publishes. The 2001ms cap is our own wal_producer_timeout_ms=2000 config — the gRPC SDK just occasionally spikes past 2 seconds. At synthetic 3-events-per-minute load this is 2 lost events; under real customer load with realistic retries this would grow. Filed as Phase 14 task #127: bump the timeout to 5 seconds, add a single retry with 100 ms backoff at the producer layer.

Consumer healthcheck status still reads unhealthy. The probe is misconfigured, cosmetically. The consumers are actually fine — they're pulling, acking, and persisting at the measured rates. Bundled with a Phase 14 healthcheck sweep.

Flow-trigger adapter parity is not empirically verified. The consumer-flow-trigger container ran throughout both canaries and the entire soak, but the load-test workspace does not have an active flow whose trigger event matched the canary payload. So we have no comparison against the direct path's Celery-based flow-trigger dispatch. We know the code path executes; we do not know it produces byte-identical downstream behavior. First design-partner engagement will surface it.

The 2-hour soak is a strong signal on synthetic idle load. It is not a long-tail signal. When we ship real customer traffic, we plan to watch a 7-day window.

The meta lesson

Reading back the eight bugs above, a pattern shows up. Every one of them slipped past thousands of green unit tests. The GCP_PROJECT_ID placeholder, the persister schema mismatch, the DeadlineExceeded gap, the topic-name prefix drift — none of these were code the tests reached in a way that exercised the failing behavior. Every one of them surfaced when we hit real Pub/Sub with real envelope shapes from a real workspace, in real production.

We got to take that risk because we have zero paying customers right now. Global INGESTION_MODE=wal cut over after 2 hours of soak, not 24. If we had customers we would not have made that call. The trade-off is the same trade-off it always is: no revenue.

"Test in production" is not a slogan, it is an admission — of what unit tests cannot see, and of the fact that some bugs are only findable after the deploy button gets pressed. What makes it defensible is the audit trail. Every canary above is anchored to a timestamp, a PR, and a metric snapshot. Every claim in this post is anchored to a file or a phase document you could open right now. If we ever want to argue that we knew what we were doing, we would like to be able to point at the receipts.

The receipts are the point. This was not a heroic push. It was a canary-gated march through a fix stack that the ADR had already laid out — plus five bugs we did not know were there until real production told us.

We are back to INGESTION_MODE=wal, sub-1% consumer CPU, 100% end-to-end parity, 20,008 events proven, and a Phase 14 backlog that starts with a 5-second timeout and a producer retry. That is where the next 48 hours begin.

The full audit trail lives in the repository: ADR-0011, ADR-0012, Phase 11 execution log, Phase 12 close, Phase 13 close and canary addendum. If you are the kind of person who reads execution logs, the docs are the primary source.