Money mark writes return HTTP 500 at 200k transactions #1495

Open
opened 2026-10-09 02:51:24 +00:00 by kayg · 6 comments
Owner

Reproduction

On the perf VM, import the benchmark's synthetic 200,000-transaction YNAB Budget with the current release server. After restarting that server, run five sequential PUT /transactions/{id}/cleared operations on the same non-reconciled row, alternating its value, then restore the original value. The benchmark honors at most two explicit Retry-After responses per logical write.

Observed

Final HTTP statuses were 500, 200, 200, 200, 500; retry counts were 1, 0, 2, 2, 2. Two requests ended with error_code=internal after the server returned retryable 503 responses. The restore succeeded. The profile therefore stopped before a valid 200k write p95 or the origin/dev comparison, and it left no changed mark behind.

Expected

A durable mark write should complete or return a documented retryable response. It should not end as an internal 500 under this realistic large Home load. Trace the response message and the Money file/Index write boundary to identify the failing component.

The profile used only synthetic fixture data. It retained no transaction content or values.

## Reproduction On the perf VM, import the benchmark's synthetic 200,000-transaction YNAB Budget with the current release server. After restarting that server, run five sequential `PUT /transactions/{id}/cleared` operations on the same non-reconciled row, alternating its value, then restore the original value. The benchmark honors at most two explicit `Retry-After` responses per logical write. ## Observed Final HTTP statuses were `500, 200, 200, 200, 500`; retry counts were `1, 0, 2, 2, 2`. Two requests ended with `error_code=internal` after the server returned retryable 503 responses. The restore succeeded. The profile therefore stopped before a valid 200k write p95 or the origin/dev comparison, and it left no changed mark behind. ## Expected A durable mark write should complete or return a documented retryable response. It should not end as an internal 500 under this realistic large Home load. Trace the response message and the Money file/Index write boundary to identify the failing component. The profile used only synthetic fixture data. It retained no transaction content or values.
Author
Owner

Additional synthetic 200k qualification evidence from the run starting 2026-10-09 02:54:30 UTC (perf VM load average 1.70/2.03/2.25): fixture import completed in 66,460.7 ms. The current release server then returned HTTP 500 (error_code=internal) for the mark restore after two explicit Retry-After: 1 retries. The benchmark stopped before saving a completed current-side sample or starting origin/dev. This run therefore has no valid 200k write p95 and no 200k comparison. The benchmark's temporary data directory was removed when the server closed; it contained only synthetic data. The earlier run recorded final write statuses 500, 200, 200, 200, 500 and a successful restore, as in the issue description.

Additional synthetic 200k qualification evidence from the run starting 2026-10-09 02:54:30 UTC (perf VM load average 1.70/2.03/2.25): fixture import completed in 66,460.7 ms. The current release server then returned HTTP 500 (`error_code=internal`) for the mark restore after two explicit `Retry-After: 1` retries. The benchmark stopped before saving a completed current-side sample or starting origin/dev. This run therefore has no valid 200k write p95 and no 200k comparison. The benchmark's temporary data directory was removed when the server closed; it contained only synthetic data. The earlier run recorded final write statuses `500, 200, 200, 200, 500` and a successful restore, as in the issue description.
Author
Owner

Traced old cleared-write path on perf VM with content-free phase logs. At 50k, p95 was 17,850.3 ms including retries; a successful 9,200.2 ms sample spent 4,311 ms between validation and source durability and 4,358 ms waiting for the projection writer, versus 86 ms validation, 14 ms totals/comparison/Account work and 163 ms SQL. These are separate tracing runs, not the earlier paired 26,554 ms sample. At 200k, an HTTP 500 is confirmed as SQLite busy (driver code 5) at BEGIN IMMEDIATE after its five-second busy timeout. A later stale-generation fallback rebuilt 200k rows: the accounts phase jumped from 83 ms to 128,415 ms. The mark-only path avoids that full replay/rewrite; transient Index errors now return 503 and retain the durable intent, with a real competing-writer regression. The suspected Tag batch is small in this synthetic fixture; no Tag code was changed. A remaining contender is the generic Notes projection of Budget Markdown; the fast-path measurement will decide whether further work is needed.

Commits: 76cf4b899 (bounded mark path), next commit adds transient-response regression. Row-write regression and SIGKILL durability-point test passed.

Traced old cleared-write path on perf VM with content-free phase logs. At 50k, p95 was 17,850.3 ms including retries; a successful 9,200.2 ms sample spent 4,311 ms between validation and source durability and 4,358 ms waiting for the projection writer, versus 86 ms validation, 14 ms totals/comparison/Account work and 163 ms SQL. These are separate tracing runs, not the earlier paired 26,554 ms sample. At 200k, an HTTP 500 is confirmed as SQLite busy (driver code 5) at BEGIN IMMEDIATE after its five-second busy timeout. A later stale-generation fallback rebuilt 200k rows: the accounts phase jumped from 83 ms to 128,415 ms. The mark-only path avoids that full replay/rewrite; transient Index errors now return 503 and retain the durable intent, with a real competing-writer regression. The suspected Tag batch is small in this synthetic fixture; no Tag code was changed. A remaining contender is the generic Notes projection of Budget Markdown; the fast-path measurement will decide whether further work is needed. Commits: 76cf4b899 (bounded mark path), next commit adds transient-response regression. Row-write regression and SIGKILL durability-point test passed.
Author
Owner

Further recovery finding: if source and projection publication complete but the final FULL intent deletion encounters SQLITE_BUSY, the next retry rebuilt the complete Budget. Recovery now settles the source journal, compares the persisted projection source fingerprint to the current source fingerprint and retries only the FULL completion fence when they match. A mismatch retains full source recovery. The mark regression adds a pending completion intent after eight mark writes and asserts recovery adds no register or Category projection writes. Category membership is also retained during marks; the selected search row is synchronized because the existing search=cleared contract searches the inline marker.

Further recovery finding: if source and projection publication complete but the final FULL intent deletion encounters SQLITE_BUSY, the next retry rebuilt the complete Budget. Recovery now settles the source journal, compares the persisted projection source fingerprint to the current source fingerprint and retries only the FULL completion fence when they match. A mismatch retains full source recovery. The mark regression adds a pending completion intent after eight mark writes and asserts recovery adds no register or Category projection writes. Category membership is also retained during marks; the selected search row is synchronized because the existing search=cleared contract searches the inline marker.
Author
Owner

Correction to the earlier writer-batching hypothesis: the traced Notes projection had zero items and zero references. That experiment has been reverted. The post-restart regression instead comes from the Note date migration: its whole-Home scan rewrites Money Markdown with Note dates, changing source fingerprints despite preserving mtime. A cleared-mark request then takes the full-history fallback; concurrent migration causes source CAS conflicts. The first incomplete qualification run reproduced 23,314 ms cleared p95 and one HTTP 409. It is diagnostic evidence, not a completed A/B result.

The server now supplies the existing Plugin ownership registry to Note date backfill. The shared scan skips foreign directories before opening files and retries keep the same exclusions. A focused regression passes with a Money file larger than the 2 MiB Note migration limit; its bytes and fingerprint stay identical while Notes, Tasks and unclaimed Markdown get their dates. This is a small necessary cross-plugin repair for #1495. No Notes projection batching remains.

A stale/missing Money generation now queues repair in the existing bounded worker and returns a retryable response instead of replaying Budget history inside a cleared-mark request. The worker serializes stale repair against server writes. Focused stale-generation regression and final gates are running. Final release measurements will replace the incomplete qualification run.

Correction to the earlier writer-batching hypothesis: the traced Notes projection had zero items and zero references. That experiment has been reverted. The post-restart regression instead comes from the Note date migration: its whole-Home scan rewrites Money Markdown with Note dates, changing source fingerprints despite preserving mtime. A cleared-mark request then takes the full-history fallback; concurrent migration causes source CAS conflicts. The first incomplete qualification run reproduced 23,314 ms cleared p95 and one HTTP 409. It is diagnostic evidence, not a completed A/B result. The server now supplies the existing Plugin ownership registry to Note date backfill. The shared scan skips foreign directories before opening files and retries keep the same exclusions. A focused regression passes with a Money file larger than the 2 MiB Note migration limit; its bytes and fingerprint stay identical while Notes, Tasks and unclaimed Markdown get their dates. This is a small necessary cross-plugin repair for #1495. No Notes projection batching remains. A stale/missing Money generation now queues repair in the existing bounded worker and returns a retryable response instead of replaying Budget history inside a cleared-mark request. The worker serializes stale repair against server writes. Focused stale-generation regression and final gates are running. Final release measurements will replace the incomplete qualification run.
Author
Owner

During #688 money688h's 200,000-row perf-VM comparison, origin/dev cc1af3c12b was OOM-killed during the cleared-mark phase. The current candidate 3ea25dc4b had completed its entire first run with zero failed marks, cleared p95 992.8 ms, amount-edit p95 15,970.8 ms, and burst RSS 5,763,231,744 bytes. This is a server crash, not a SLOW-only observation.

The VM has 7,879 MiB RAM and no swap. Both binaries used the same synthetic Home and production web build, under a single perf-run lock; the raw candidate run and partial pair are retained in docs/perf/baseline.json. The comparison aborted with browser TypeError: Failed to fetch, so no origin/dev p95 or completed 200k pair is claimed.

Kernel evidence, 2026-10-09 08:30:48 CEST:

oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=user.slice,mems_allowed=0,global_oom,task_memcg=/user.slice/user-0.slice/session-c14938.scope,task=origin-dev-serv,pid=2214522,uid=0
Out of memory: Killed process 2214522 (origin-dev-serv) total-vm:9385148kB, anon-rss:5634884kB, file-rss:28kB, shmem-rss:0kB, UID:0 pgtables:12212kB oom_score_adj:0

Reproduce with bench/money-register-688.mjs, MONEY688_ROWS=200000, MONEY688_PAIRS=3, the origin/dev and candidate release binaries, Chromium on the perf VM. Build elsewhere and hold perf-run's shared lock. No test expectation or memory budget was changed. The owner must review the crash before claiming that origin/dev handles the 200k workload.

During #688 money688h's 200,000-row perf-VM comparison, origin/dev cc1af3c12b68ad26c8403adde1be39c096b9ddea was OOM-killed during the cleared-mark phase. The current candidate 3ea25dc4b had completed its entire first run with zero failed marks, cleared p95 992.8 ms, amount-edit p95 15,970.8 ms, and burst RSS 5,763,231,744 bytes. This is a server crash, not a SLOW-only observation. The VM has 7,879 MiB RAM and no swap. Both binaries used the same synthetic Home and production web build, under a single perf-run lock; the raw candidate run and partial pair are retained in docs/perf/baseline.json. The comparison aborted with browser TypeError: Failed to fetch, so no origin/dev p95 or completed 200k pair is claimed. Kernel evidence, 2026-10-09 08:30:48 CEST: ``` oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=user.slice,mems_allowed=0,global_oom,task_memcg=/user.slice/user-0.slice/session-c14938.scope,task=origin-dev-serv,pid=2214522,uid=0 Out of memory: Killed process 2214522 (origin-dev-serv) total-vm:9385148kB, anon-rss:5634884kB, file-rss:28kB, shmem-rss:0kB, UID:0 pgtables:12212kB oom_score_adj:0 ``` Reproduce with bench/money-register-688.mjs, MONEY688_ROWS=200000, MONEY688_PAIRS=3, the origin/dev and candidate release binaries, Chromium on the perf VM. Build elsewhere and hold perf-run's shared lock. No test expectation or memory budget was changed. The owner must review the crash before claiming that origin/dev handles the 200k workload.
Author
Owner

money688h final: head a5aaf55009, measured runtime 3ea25dc4b. Full report and verbatim gates posted on #688.

The original 200k HTTP 500 was SQLite BUSY at BEGIN IMMEDIATE. The fix retains durable intents on retryable contention, removes mark-triggered Budget replay, and excludes foreign Money sources from Note date migration, scans and live adoption. Selected-row SQL uses the transaction index. Constant-row tests, incremental/full replay properties and SIGKILL recovery pass.

Three 50k default-allocator pairs: median candidate/origin cleared p95 299.8/3228.5 ms; amount p95 1192.7/3277.2 ms. Candidate individual cleared p95s 340.0,299.8,277.3 ms: the first exceeds 300 ms. Every measured write succeeded.

Default 200k candidate run succeeded, cleared p95 992.8 ms; origin/dev was OOM-killed, filed #1502. This attempt has zero complete pairs. A separately labelled comparison applies MALLOC_ARENA_MAX=2 and MALLOC_TRIM_THRESHOLD_=131072 equally to both servers, harness and Chromium: three complete 200k pairs, all writes successful, median cleared p95 963.3/14401.6 ms and amount p95 12942.8/13707.0 ms. Raw statuses, retries, CPU/RSS, load5 and hashes are committed in baseline.json. This does not erase the default-settings crash.

Full server gates had one SLOW-only Calendar budget failure; its isolated parent retry and both integration targets passed. No expectation or latency budget changed. Production UI browser exceptions remain filed as #1498; real-Mac timing was not run. No push, deploy or issue closure. Cargo output and local web build output cleaned.

money688h final: head a5aaf55009efafc6a77239124375a74769fc8620, measured runtime 3ea25dc4b. Full report and verbatim gates posted on #688. The original 200k HTTP 500 was SQLite BUSY at BEGIN IMMEDIATE. The fix retains durable intents on retryable contention, removes mark-triggered Budget replay, and excludes foreign Money sources from Note date migration, scans and live adoption. Selected-row SQL uses the transaction index. Constant-row tests, incremental/full replay properties and SIGKILL recovery pass. Three 50k default-allocator pairs: median candidate/origin cleared p95 299.8/3228.5 ms; amount p95 1192.7/3277.2 ms. Candidate individual cleared p95s 340.0,299.8,277.3 ms: the first exceeds 300 ms. Every measured write succeeded. Default 200k candidate run succeeded, cleared p95 992.8 ms; origin/dev was OOM-killed, filed #1502. This attempt has zero complete pairs. A separately labelled comparison applies MALLOC_ARENA_MAX=2 and MALLOC_TRIM_THRESHOLD_=131072 equally to both servers, harness and Chromium: three complete 200k pairs, all writes successful, median cleared p95 963.3/14401.6 ms and amount p95 12942.8/13707.0 ms. Raw statuses, retries, CPU/RSS, load5 and hashes are committed in baseline.json. This does not erase the default-settings crash. Full server gates had one SLOW-only Calendar budget failure; its isolated parent retry and both integration targets passed. No expectation or latency budget changed. Production UI browser exceptions remain filed as #1498; real-Mac timing was not run. No push, deploy or issue closure. Cargo output and local web build output cleaned.
Commenting is not possible because the repository is archived.
No labels
No milestone
No project
No assignees
1 participant
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/calternal-v0#1495
No description provided.