Skip to content

fix(dc-plan): unblock startup and stop refresh sync amplification - #231

Merged
shark0F0497 merged 4 commits into
main-v2from
fix/dc-plan-sync-amplification
Sep 17, 2026
Merged

shark0F0497 merged 4 commits into
main-v2from
fix/dc-plan-sync-amplification

Conversation

@shark0F0497

Copy link
Copy Markdown
Collaborator

Pull Request Checklist

  • Code follows the style guidelines
  • Tests pass locally (go test ./...)
  • Code is formatted (gofmt -l ./ clean, golangci-lint run ./... 0 issues)
  • Documentation updated if needed (not needed)
  • Commit messages follow conventional commits
  • PR description is complete and clear

Summary

Unblocks Start() from the Hilbert dc plan sync, stops POST /operator/plans/refresh from running a full workspace sync per request, and records the composite indexes that the sync relies on.


Motivation

On 2026-09-17 the mercury keystone deployment was serving no traffic: the pod was 0/1, the Service had no ready endpoint, and the container restarted every 180 seconds. Four independent defects combined, and each is addressed here.

1. A slow startup sync gated readiness. Start() ran syncWorkspacesOnStartup() and syncDCPlansOnStartup() before starting the HTTP listener. The sync never finished inside the 180s startup probe, so the container was killed mid-transaction, the sync rolled back, and the next start repeated exactly the same work — a deterministic loop (6 restarts observed).

2. The sync was slow because of a missing composite index. The sync issues

UPDATE tasks SET status = 'cancelled', updated_at = ?
WHERE dc_plan_id = ? AND status = 'pending' AND deleted_at IS NULL

once per collected plan (514 of them, all inside one transaction). tasks had no usable composite index, so the planner used index_merge(intersect(idx_dc_plan, idx_status)) and scanned every status = 'pending' entry. EXPLAIN ANALYZE measured actual rows = 109053 on that branch and 1955 ms for a statement addressing eleven plans. With (dc_plan_id, status, deleted_at) the same statement is a covering index lookup at 0.063 ms.

3. refresh amplified one request into a full workspace sync. RefreshOperatorPlans ran SyncWorkspace inline before returning the plan list, and one SyncWorkspace costs O(plan count) transactions because the workstation projector and the pending pool each begin a transaction per plan (ws=12 with 150 plans ≈ 300 transactions; ws=4 with 583 plans ≈ 1166). Every activated device polls this endpoint, so requests amplified 1:1 into full syncs: 74 requests → 69 syncs → ~22,000 transactions in 3 minutes against a 25-connection pool, which produced 476 deadlocks and 5,712 context deadline exceeded events in 3 minutes and exhausted the pool.

4. Two paths deadlocked on a lock-order cycle. SHOW ENGINE INNODB STATUS showed the pending pool path holding workstations and waiting for data_collectors, while the projector held data_collectors and waited for workstations. Both lock rows they only read. The index in (2) shrank each footprint from hundreds of rows to one or two, which stopped the observed deadlocks, but the ordering conflict was untouched.


Changes

Modified Files

  • [internal/server/server.go](internal/server/server.go)Start() no longer calls the two startup syncs before the listener; startPeriodicDCPlanSync() now runs them inside its goroutine, immediately before entering the ticker loop. syncDCPlansOnStartup() is deleted. The startup workspace sync now takes a context so shutdown can cancel it.
  • [internal/api/handlers/dc_plan.go](internal/api/handlers/dc_plan.go)RefreshOperatorPlans returns the current projection instead of syncing first. The response contract, path, auth and fields are unchanged.
  • [internal/api/handlers/operator_plan_test.go](internal/api/handlers/operator_plan_test.go)fakeOperatorPlanSyncer counts calls. TestRefreshOperatorPlansFallsBackToStaleProjection tested the removed inline path and is replaced by TestRefreshOperatorPlansDoesNotSyncInline.
  • [internal/services/dc_plan_workstation_projection.go](internal/services/dc_plan_workstation_projection.go)resolveProjectionCollector and resolveProjectionRobot no longer take row locks; both are read-only and the write that follows targets workstations. ensureProjectedWorkstation keeps its lock, with a comment explaining why: the unique indexes on workstations only cover is_current rows, so the gap lock on a missing row is what prevents two concurrent projectors from inserting duplicate workstations.
  • [internal/services/dc_plan_task_supply.go](internal/services/dc_plan_task_supply.go)loadTaskSupplyWorkstation no longer takes row locks; it is a read-only lookup whose only write that follows targets tasks, and its three-table join previously locked every scanned row.

Added Files

  • [internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.up.sql](internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.up.sql) — adds tasks(dc_plan_id, status, deleted_at), data_collectors(operator_id, deleted_at), robots(device_id, deleted_at), workstations(workspace_id, deleted_at) and episodes(deleted_at, dc_plan_id, cloud_synced, qa_status, duration_sec).
  • [internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.down.sql](internal/storage/database/migrations/v2/000023_dc_plan_sync_lookup_indexes.down.sql) — drops them.

The migration guards every statement with an information_schema check and runs the DDL with ALGORITHM=INPLACE, LOCK=NONE. This matters: production already carries all five indexes because they were created by hand while the incident was being handled, and a plain ADD INDEX would abort the migration. cmd/keystone-edge/main.go calls logger.Fatalf when migration fails, and golang-migrate marks schema_migrations_v2 dirty before executing, so an aborted migration is fatal at startup and blocks every later migration.


Type of Change

  • Bug fix (non-breaking change that fixes an issue)
  • New feature
  • Breaking change
  • Documentation update
  • Refactoring (code improvement without functional changes)
  • Performance improvement
  • Test changes

Impact Analysis

Breaking Changes

None. No API path, request field or response field changes.

Backward Compatibility

Fully backward compatible for clients. Devices need no changes: ego-portal still calls POST /operator/plans/refresh on the same schedule and reads the same fields.

One behaviour change worth flagging to reviewers: plan and workstation freshness is now bounded by the periodic sync interval (currently 5 minutes) plus the device's own poll interval (60s), instead of being forced on every refresh. This was discussed and accepted. stale in the response now means "the projection was not synced for this request" and is false while the sync service is configured; ego-portal reads only items, not stale.


Testing

Test Cases

  • Unit tests pass locally (go test ./...)
  • gofmt -l ./ clean, go vet ./... clean
  • golangci-lint run ./... reports 0 issues
  • The new regression test is verified to fail on the previous code

Test Coverage

  • New tests added
  • Existing tests updated

TestRefreshOperatorPlansDoesNotSyncInline issues five requests against a counting fake and asserts SyncWorkspace is never called. On the previous code it fails with refresh must not sync, but SyncWorkspace was called 5 time(s), which is the 1:1 amplification measured in production.

Gaps reviewers should know about

  • The lock-order change cannot be covered by tests. Tests run on modernc.org/sqlite and both *ForUpdateClause helpers return an empty string for sqlite, so FOR UPDATE is never exercised and sqlite has no deadlock semantics. This change rests on review and production observation.
  • The migration was executed against production to confirm it is a safe no-op there (rc=0, all five indexes intact). The branch where the indexes do not exist yet — building them online — has not been exercised on a staging clone.

Performance Impact

Measured on the production database during and after the incident-handling index change:

Metric Before After
Row lock waits +2,224 / minute +0 over 4.5 minutes
Deadlocks 476 / 3 minutes 0
context deadline exceeded 5,712 / 3 minutes 0
keystone connections 25 / 25 saturated 6
Innodb_data_read ~5 GB / minute ~0
  • Memory usage: No change
  • CPU usage: No change
  • Throughput: POST /operator/plans/refresh drops from seconds (waiting for a full sync) to single-digit milliseconds
  • Lock contention: Reduced — smaller index ranges for the sync lookups, and the read-only lookups no longer take row locks

The periodic sync still performs O(plan count) transactions (~2,300 per round for 1,822 plans) and takes ~33 seconds per round, of which the database accounts for under 10 seconds and the remainder is the Hilbert HTTP fetch. Batching those transactions is a deliberate follow-up, not part of this PR.


Documentation

  • No documentation changes needed

Related Issues

  • Refers to the 2026-09-17 mercury keystone outage

Additional Notes

Operational notes for whoever deploys this:

  1. schema_migrations_v2 on production is at version=22, dirty=0, so this migration advances it to 23.
  2. POST /api/v1/workspaces/{workspace_id}/dc-plans/sync (admin-only) still exists and is the only manual convergence trigger. It is the fallback if the ticker ever stalls, but it should not be called in a loop: SyncWorkspace still has no per-workspace mutex.
  3. After deployment, [SERVER] Starting HTTP server should appear before the [HILBERT-SYNC] lines, and the pod should reach 1/1 immediately rather than after a 180s probe timeout.
  4. MySQL's innodb_buffer_pool_size, previously reverted to the 128 MB default on restart, has been persisted separately on production with SET PERSIST.

Deliberately not included

Kept out to keep this PR focused and independently revertible:

  • batching the per-plan transactions in the projector and the pending pool
  • a per-workspace mutex in SyncWorkspace
  • POST /workspaces/:id/dc-plans/sync still locks the plan row via loadTaskSupplyPlan; that lock has weak value but is left alone for now
  • shortening dcPlanAutoSyncInterval

Notes for Reviewers

  • Please focus on internal/server/server.go: the two startup syncs moved into the periodic goroutine, so they now run concurrently with request handling instead of before it, and shutdown waits on them. The goroutine closes done in a defer, so Shutdown still returns; the context passed is cancellable.
  • Please check that dropping the two read-only locks is sound. The argument is that neither lookup writes the table it reads and the only write that follows is against tasks. The lock in ensureProjectedWorkstation must stay.
  • The migration's guards are there for production's benefit. If reviewers prefer plain ADD INDEX plus an operational step, that is a valid alternative — but a failed migration is fatal at startup and leaves the version dirty.

Checklist for Reviewers

  • Code changes are correct and well-implemented
  • Tests are adequate and pass
  • No unintended side effects
  • Performance impact is acceptable
  • Backward compatibility maintained

Start() ran the workspace and dc_plan startup syncs before starting the
HTTP listener. A slow Hilbert round therefore blocked readiness, the
startup probe killed the container after 180s, the sync transaction
rolled back with the sync not committed, and the next attempt repeated
exactly the same work forever.

Move both startup syncs into the periodic DC plan sync goroutine and
start that goroutine after the listener, so convergence can never gate
readiness. The goroutine now converges once immediately before entering
the ticker loop, which also removes the previous wait of up to one full
ticker period after a restart, and it uses the cancellable context so
shutdown can interrupt an in-flight sync.
POST /operator/plans/refresh ran a full SyncWorkspace inline before
returning the operator's plans. One SyncWorkspace costs O(plan count)
transactions: the workstation projector begins a transaction per plan
and the Ego Portal pending pool begins another, so a 150-plan workspace
cost about 300 transactions and a 583-plan workspace about 1166. With
every activated device polling the endpoint, requests amplified 1:1 into
full workspace syncs, exhausted the 25-connection pool and produced
thousands of deadlocks and lock wait timeouts per minute.

Return the current projection instead and leave convergence to the
periodic hilbert sync, which already runs every five minutes and repairs
missing workstations idempotently. Plans and workstations can now lag by
up to one sync period, which the collection workflow accepts.

TestRefreshOperatorPlansFallsBackToStaleProjection tested the removed
inline path (it asserted stale=true when the inline sync failed), so it
is replaced with TestRefreshOperatorPlansDoesNotSyncInline, which fails
on the previous behaviour with five syncs for five requests.
Records the indexes that were created by hand while the dc plan sync
outage was being handled, so a rebuilt database cannot reproduce it.

Without these indexes the planner falls back to single column indexes
whose leading column is non selective (status = 'pending',
deleted_at IS NULL), so a statement addressing one plan still scans a
large index range. With SELECT ... FOR UPDATE InnoDB locks every row it
scans, which is how one per plan UPDATE came to hold hundreds of row
locks for seconds and how the two sync paths deadlocked.

The statements are guarded with information_schema checks because
databases patched during the incident already carry these indexes: a
plain ADD INDEX would abort the migration, and a failed migration is
fatal at startup and leaves schema_migrations_v2 dirty, blocking every
later migration.

Verified against the production database, where all five indexes already
exist, so the up migration is a no-op and exits cleanly.
The workstation projector and the pending pool both lock rows they only
read, and they reach those tables in opposite order:

  pending pool:  workstations -> data_collectors -> robots
  projector:     data_collectors -> robots -> workstations

InnoDB reported the resulting deadlock as one transaction holding
workstations while waiting for data_collectors, and the other holding
data_collectors while waiting for workstations. The index added earlier
shrank each footprint from hundreds of rows to one or two, which stopped
the observed deadlocks, but the ordering conflict is unchanged: any
second concurrent sync of the same workspace brings it back.

None of the three lookups below writes the table it reads, and the only
write that follows is against tasks, so the lock buys nothing.

The lock in ensureProjectedWorkstation is kept deliberately. It is the
one that matters for correctness: the unique indexes on workstations only
cover is_current rows, so the gap lock taken on a missing row is what
stops two concurrent projectors from inserting duplicate workstations.

The test suite cannot cover this change. Tests run on sqlite and both
helpers return an empty clause for sqlite, so FOR UPDATE is never
exercised; the change rests on review and on production observation.
@shark0F0497
shark0F0497 merged commit 8d2b2cb into main-v2 Sep 17, 2026
4 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant