Audit: server and bulk operations that are far slower than they should be #1374

Closed
opened 2026-10-07 14:58:17 +00:00 by kayg · 28 comments
Owner

Owner 2026-10-07, after Tag rename took 45 s for 1,000 Notes: "please check other operations in the app that take too long when should be sub-millisecond." This issue owns a server-side audit of every API operation and every bulk operation: measure, rank, file one issue per cause.
Targets: Index reads (lists, item detail, counts, search page) p50 <= 1 ms server time and p95 <= 5 ms on a warm Index; single-item writes acknowledged <= 10 ms; bulk operations (rename/merge Tag, move or rename a folder with 1,000 children, delete/trash/restore 1,000 items, mark 1,000 Mails read, bulk Task complete, Money import of 2,000 rows, share/unshare a folder, Hide/Unhide many) visible to the User <= 500 ms via the durable-intent pattern (one Index transaction + receipt, background file work with batched durability), other requests p95 <= 50 ms while they run.

Owner 2026-10-07, after Tag rename took 45 s for 1,000 Notes: "please check other operations in the app that take too long when should be sub-millisecond." This issue owns a server-side audit of every API operation and every bulk operation: measure, rank, file one issue per cause. Targets: Index reads (lists, item detail, counts, search page) p50 <= 1 ms server time and p95 <= 5 ms on a warm Index; single-item writes acknowledged <= 10 ms; bulk operations (rename/merge Tag, move or rename a folder with 1,000 children, delete/trash/restore 1,000 items, mark 1,000 Mails read, bulk Task complete, Money import of 2,000 rows, share/unshare a folder, Hide/Unhide many) visible to the User <= 500 ms via the durable-intent pattern (one Index transaction + receipt, background file work with batched durability), other requests p95 <= 50 ms while they run.
Author
Owner

Starting #1374 on job/apiaudit-1374, based on origin/dev at 0419170fe456b58614befcb12d9c9d255118f1c0. I am reading the API contracts and existing fixtures, then I will seed a disposable Home, run the read and bulk sweeps, and record findings in docs/perf/2026-10-07-1374-api-audit.md. Scope remains the audit harness and report.

Starting #1374 on `job/apiaudit-1374`, based on `origin/dev` at `0419170fe456b58614befcb12d9c9d255118f1c0`. I am reading the API contracts and existing fixtures, then I will seed a disposable Home, run the read and bulk sweeps, and record findings in `docs/perf/2026-10-07-1374-api-audit.md`. Scope remains the audit harness and report.
Author
Owner

Initial contract finding (source SHA 0419170fe456b58614befcb12d9c9d255118f1c0): the generated OpenAPI contract exposes only single-item state writes for the requested Mail and Task operations: POST /api/v1/mail/messages/{id}/read-state takes one message ID, and POST /api/v1/notes/tasks/tick takes one task_id. PUT /api/v1/tags/hidden also takes one path. I will measure each 1,000-item UI-equivalent operation as bounded per-item requests and report the absence of a batch contract separately from measured latency. This is contract evidence; I have not yet measured those writes.

Initial contract finding (source SHA `0419170fe456b58614befcb12d9c9d255118f1c0`): the generated OpenAPI contract exposes only single-item state writes for the requested Mail and Task operations: `POST /api/v1/mail/messages/{id}/read-state` takes one message ID, and `POST /api/v1/notes/tasks/tick` takes one `task_id`. `PUT /api/v1/tags/hidden` also takes one `path`. I will measure each 1,000-item UI-equivalent operation as bounded per-item requests and report the absence of a batch contract separately from measured latency. This is contract evidence; I have not yet measured those writes.
Author
Owner

Source-scan finding: crates/plugins/files/src/lib.rs::restore calls state.root.list_trash(&home) for every single-item restore, then derives the Sidecars for that one parent. With 1,000 trashed entries, 1,000 restore requests can each enumerate the full Trash listing (up to roughly 1,000,000 entry visits). I will cap the measured restore sample at 100 and extrapolate to 1,000 under the issue's two-minute rule. The source is not yet measured on this Home.

Source-scan finding: `crates/plugins/files/src/lib.rs::restore` calls `state.root.list_trash(&home)` for every single-item restore, then derives the Sidecars for that one parent. With 1,000 trashed entries, 1,000 restore requests can each enumerate the full Trash listing (up to roughly 1,000,000 entry visits). I will cap the measured restore sample at 100 and extrapolate to 1,000 under the issue's two-minute rule. The source is not yet measured on this Home.
Author
Owner

Seed progress at 2026-10-07 17:34 UTC: 250 of 2,000 Note create requests completed after about 12 minutes. The OpenAPI contract has no bulk Note-create route. The harness continues under the 20-minute seed deadline; it will report the final count and skip dependent Task measurements if 1,000 Tasks do not settle. This is a shared-host measurement, not a stable performance baseline.

Seed progress at 2026-10-07 17:34 UTC: 250 of 2,000 Note create requests completed after about 12 minutes. The OpenAPI contract has no bulk Note-create route. The harness continues under the 20-minute seed deadline; it will report the final count and skip dependent Task measurements if 1,000 Tasks do not settle. This is a shared-host measurement, not a stable performance baseline.
Author
Owner

Seed completed at 2026-10-07 17:43 UTC: 485/2,000 Notes in 20.3 minutes through POST /api/v1/notes. Calendar Events (0/12), Files (0/5,000), the second User/share, Mail (0/2,000), and Money (0/2,000) were skipped when the shared 20-minute seed deadline expired. The first 100 Notes are the Task fixture; the API sweep will report its settled count. Source scan: crates/plugins/notes/src/lib.rs::create does one store::write and store::index per Note under the per-User lock; OpenAPI exposes no bulk Note-create route. This is a shared-host result, not a stable baseline.

Seed completed at 2026-10-07 17:43 UTC: 485/2,000 Notes in 20.3 minutes through POST /api/v1/notes. Calendar Events (0/12), Files (0/5,000), the second User/share, Mail (0/2,000), and Money (0/2,000) were skipped when the shared 20-minute seed deadline expired. The first 100 Notes are the Task fixture; the API sweep will report its settled count. Source scan: crates/plugins/notes/src/lib.rs::create does one `store::write` and `store::index` per Note under the per-User lock; OpenAPI exposes no bulk Note-create route. This is a shared-host result, not a stable baseline.
Author
Owner

At 2026-10-07 18:12 UTC, the 1,000-Task completion action had not returned. Ten loopback connections from the harness to the audit server remained established with empty send and receive queues. This exceeds the 150 ms action target; final acknowledgement, visibility, completion and competing-GET timings are pending. The Task stage was enabled from the partial Notes fixture; the final Task count is pending the harness output.

At 2026-10-07 18:12 UTC, the 1,000-Task completion action had not returned. Ten loopback connections from the harness to the audit server remained established with empty send and receive queues. This exceeds the 150 ms action target; final acknowledgement, visibility, completion and competing-GET timings are pending. The Task stage was enabled from the partial Notes fixture; the final Task count is pending the harness output.
Author
Owner

Source finding while the 1,000-Task batch is active: crates/plugins/notes/src/tasks_api.rs::tick acquires lock_user, reads the Task's Markdown source, replaces its status, and refreshes the Task Index before releasing the lock. All 1,000 requests use the same User, so they serialize through this path. This predicts a run over two minutes and explains why a 100-Task sample would have been the correct time-boxed size. The current 1,000-item run remains in progress; final timing is pending. Related UI behavior is tracked by #1229.

Source finding while the 1,000-Task batch is active: `crates/plugins/notes/src/tasks_api.rs::tick` acquires `lock_user`, reads the Task's Markdown source, replaces its status, and refreshes the Task Index before releasing the lock. All 1,000 requests use the same User, so they serialize through this path. This predicts a run over two minutes and explains why a 100-Task sample would have been the correct time-boxed size. The current 1,000-item run remains in progress; final timing is pending. Related UI behavior is tracked by #1229.
Author
Owner

Completed the time-boxed discovery audit. The result and gaps are recorded in docs/perf/2026-10-07-1374-api-audit.md.

The audit reached its three-hour limit before the bulk sweep returned. The seed created 485/2,000 Notes in 20.3 minutes (23.9/min). Calendar, Files, the second User/shared folder, Mail and Money fixtures did not start before the seed deadline. The harness sampled 96 GET/HEAD operations and skipped 89, but per-operation timings were in memory and were not preserved when the run stopped. The 1,000-Task operation was still active; its acknowledgement, visibility and competing-read timings are unavailable. No ranked read timing or query-plan table can be claimed.

Source findings and deduplication are in the report. Tag rewrite is already tracked by #1186; the full-Trash lookup pattern is tracked by #979; related Task UI/Undo work is #1229, Task view latency is #1286, and read projections are #699 and #687. I filed no new cause issues without completed timing evidence.

Decisions: used the 150 ms visible-state target from DESIGN §59; limited the Files restore sample to 100 because each restore scans Trash; did not refile #1186.

Branch head: 828031e99c.
git fetch origin && git merge origin/dev: Already up to date.

bun run check exited 0. Captured gate output:
PASS production dependency licences: 759 locked package releases across apps/web, apps/docs and packages
perf-lint: PASS; 0 violations; 22544 scoped exceptions
svelte-check found 0 errors and 1 warning in 1 file

The warning is packages/ui/src/components/calendar/AttachmentDeck.svelte:1055: “Do not use empty rulesets (css)”. No Rust source changed, so Rust gates did not apply. cargo clean output: Removed 9259 files, 3.4GiB total. Audit data and web build output were removed.

Completed the time-boxed discovery audit. The result and gaps are recorded in docs/perf/2026-10-07-1374-api-audit.md. The audit reached its three-hour limit before the bulk sweep returned. The seed created 485/2,000 Notes in 20.3 minutes (23.9/min). Calendar, Files, the second User/shared folder, Mail and Money fixtures did not start before the seed deadline. The harness sampled 96 GET/HEAD operations and skipped 89, but per-operation timings were in memory and were not preserved when the run stopped. The 1,000-Task operation was still active; its acknowledgement, visibility and competing-read timings are unavailable. No ranked read timing or query-plan table can be claimed. Source findings and deduplication are in the report. Tag rewrite is already tracked by #1186; the full-Trash lookup pattern is tracked by #979; related Task UI/Undo work is #1229, Task view latency is #1286, and read projections are #699 and #687. I filed no new cause issues without completed timing evidence. Decisions: used the 150 ms visible-state target from DESIGN §59; limited the Files restore sample to 100 because each restore scans Trash; did not refile #1186. Branch head: 828031e99c7563a400a4e51a6cb438f432dc2d73. git fetch origin && git merge origin/dev: Already up to date. bun run check exited 0. Captured gate output: PASS production dependency licences: 759 locked package releases across apps/web, apps/docs and packages perf-lint: PASS; 0 violations; 22544 scoped exceptions svelte-check found 0 errors and 1 warning in 1 file The warning is packages/ui/src/components/calendar/AttachmentDeck.svelte:1055: “Do not use empty rulesets (css)”. No Rust source changed, so Rust gates did not apply. cargo clean output: Removed 9259 files, 3.4GiB total. Audit data and web build output were removed.
Author
Owner

Correction to my previous final comment: the bulk target in issue #1374 is visible result within 500 ms and other-request p95 <= 50 ms. DESIGN §59's 150 ms target applies to input-to-visible accepted interaction state. I corrected the report to distinguish them.

Updated report: docs/perf/2026-10-07-1374-api-audit.md
Updated branch head: 02b465c294eac
The audit remains incomplete for the timing and fixture reasons in the report; no new timing results were produced by this documentation correction.

Correction to my previous final comment: the bulk target in issue #1374 is visible result within 500 ms and other-request p95 <= 50 ms. DESIGN §59's 150 ms target applies to input-to-visible accepted interaction state. I corrected the report to distinguish them. Updated report: docs/perf/2026-10-07-1374-api-audit.md Updated branch head: 02b465c294eac The audit remains incomplete for the timing and fixture reasons in the report; no new timing results were produced by this documentation correction.
Author
Owner

Full branch head SHA for the report correction: 02b465c299.

Full branch head SHA for the report correction: 02b465c299ca3e58ab331fecbc0b5a9659dbbf92.
Author
Owner

Continuing #1374 on job/apiaudit-1374, head 02b465c299ca3e58ab331fecbc0b5a9659dbbf92, based at 0419170fe456b58614befcb12d9c9d255118f1c0. I read the prior report and comments. The earlier run is incomplete: it has no durable timing rows. This rerun will use file-backed Home fixtures before the measured server start, measure startup indexing, cap API-only fixtures, append each sample to CSV, and run on the perf VM under its lock. I will update the ranked table only with completed samples.

Continuing #1374 on `job/apiaudit-1374`, head `02b465c299ca3e58ab331fecbc0b5a9659dbbf92`, based at `0419170fe456b58614befcb12d9c9d255118f1c0`. I read the prior report and comments. The earlier run is incomplete: it has no durable timing rows. This rerun will use file-backed Home fixtures before the measured server start, measure startup indexing, cap API-only fixtures, append each sample to CSV, and run on the perf VM under its lock. I will update the ranked table only with completed samples.
Author
Owner

Continuing #1374 in job/apiaudit-1374 from head a9efd32193066959a2aab318a34be2b49850ba1e. The runner previously lost its remote perf-run session before it produced any measurement. Commit 5862b1492169781fc00184d0954086f0a9426c6b detaches that lock-held process and records a remote exit marker. It also appends read samples, bulk visibility observations and timed-out lower bounds as they happen. No new measurement result is claimed yet.

Continuing #1374 in `job/apiaudit-1374` from head `a9efd32193066959a2aab318a34be2b49850ba1e`. The runner previously lost its remote `perf-run` session before it produced any measurement. Commit `5862b1492169781fc00184d0954086f0a9426c6b` detaches that lock-held process and records a remote exit marker. It also appends read samples, bulk visibility observations and timed-out lower bounds as they happen. No new measurement result is claimed yet.
Author
Owner

Rerun attempt 1 acquired the perf lock after #1362, then its detached launcher exited with status 127 before the server started. Evidence: the saved CSV contains only the direct Home seed row and there is no startup Index timing. The disposable remote audit root has been removed. I am replacing the nested shell quoting with two remote script files and an absolute perf-run path, then I will rerun the audit. Current head: 5862b1492169781fc00184d0954086f0a9426c6b.

Rerun attempt 1 acquired the perf lock after #1362, then its detached launcher exited with status 127 before the server started. Evidence: the saved CSV contains only the direct Home seed row and there is no startup Index timing. The disposable remote audit root has been removed. I am replacing the nested shell quoting with two remote script files and an absolute `perf-run` path, then I will rerun the audit. Current head: `5862b1492169781fc00184d0954086f0a9426c6b`.
Author
Owner

Runner fix committed as 900a9b630fa91a7453fff54cf2661afa65f01963: the remote server-<phase>.sh and runner-<phase>.sh are now decoded from bounded Base64 arguments, and the latter calls /usr/local/bin/perf-run directly. A one-second detached-script smoke check passed after its SSH launch returned. The new run will use fresh fixture Users and overwrite the primary timing CSV; the first attempt's seed-only CSV is retained locally as launch-failure-attempt-1.csv.

Runner fix committed as `900a9b630fa91a7453fff54cf2661afa65f01963`: the remote `server-<phase>.sh` and `runner-<phase>.sh` are now decoded from bounded Base64 arguments, and the latter calls `/usr/local/bin/perf-run` directly. A one-second detached-script smoke check passed after its SSH launch returned. The new run will use fresh fixture Users and overwrite the primary timing CSV; the first attempt's seed-only CSV is retained locally as `launch-failure-attempt-1.csv`.
Author
Owner

Startup diagnosis: the second attempt also exited 127 before readiness. ldd on the shared release binary showed libsherpa-onnx-c-api.so and libonnxruntime.so resolving from /mnt/hdd/targets/shared-server/target/...; that path is absent on the perf VM. The VM had the executable but not its two non-system runtime libraries, and stderr was sent to /dev/null, which hid the loader error. I will include that 31 MiB library directory in the transfer and set LD_LIBRARY_PATH, then verify dependency resolution remotely before the next measurement run. No API timing data was produced. Head: 900a9b630fa91a7453fff54cf2661afa65f01963.

Startup diagnosis: the second attempt also exited 127 before readiness. `ldd` on the shared release binary showed `libsherpa-onnx-c-api.so` and `libonnxruntime.so` resolving from `/mnt/hdd/targets/shared-server/target/...`; that path is absent on the perf VM. The VM had the executable but not its two non-system runtime libraries, and stderr was sent to `/dev/null`, which hid the loader error. I will include that 31 MiB library directory in the transfer and set `LD_LIBRARY_PATH`, then verify dependency resolution remotely before the next measurement run. No API timing data was produced. Head: `900a9b630fa91a7453fff54cf2661afa65f01963`.
Author
Owner

Fix committed at 8725da018afec30a23643b657d1dddd91c26546f. The audit runner now discovers the shared binary's non-system libraries with ldd, copies the resolved library directory with the release binary, sets LD_LIBRARY_PATH on the perf VM, and checks remote ldd output before queuing the server start. The two failed attempts each produced only a seed row; those CSVs remain under local target/tmp/api-audit-1374/launch-failure-attempt-{1,2}.csv. I am starting the corrected run now.

Fix committed at `8725da018afec30a23643b657d1dddd91c26546f`. The audit runner now discovers the shared binary's non-system libraries with `ldd`, copies the resolved library directory with the release binary, sets `LD_LIBRARY_PATH` on the perf VM, and checks remote `ldd` output before queuing the server start. The two failed attempts each produced only a seed row; those CSVs remain under local `target/tmp/api-audit-1374/launch-failure-attempt-{1,2}.csv`. I am starting the corrected run now.
Author
Owner

The locked dependency test resolved the copied libsherpa-onnx-c-api.so and libonnxruntime.so from runtime-check/server-libs; ldd reported no missing libraries. The full artifact-copy preflight had returned “not found”, so the mismatch is in its transfer staging. I will stage the 31 MiB library files as regular files instead of a directory symlink, assert each expected library resolves, and preserve a short server startup diagnostic if the next launch exits early. The runtime test used perf-run; it did not start the server or run the API audit.

The locked dependency test resolved the copied `libsherpa-onnx-c-api.so` and `libonnxruntime.so` from `runtime-check/server-libs`; `ldd` reported no missing libraries. The full artifact-copy preflight had returned “not found”, so the mismatch is in its transfer staging. I will stage the 31 MiB library files as regular files instead of a directory symlink, assert each expected library resolves, and preserve a short server startup diagnostic if the next launch exits early. The runtime test used `perf-run`; it did not start the server or run the API audit.
Author
Owner

Exact transfer bug found: server-libs was staged locally but omitted from the tar argument list, so the perf VM never received it. The lock-held runtime check passed when it explicitly transferred the binary and server-libs; ldd resolved both expected libraries. Commit 88162d782fae7a030d1451b2c0edb21e12054e42 adds the directory to the full transfer, copies it as regular files, and checks each dependency before startup. I am retrying the audit with this fixed transfer.

Exact transfer bug found: `server-libs` was staged locally but omitted from the `tar` argument list, so the perf VM never received it. The lock-held runtime check passed when it explicitly transferred the binary and `server-libs`; `ldd` resolved both expected libraries. Commit `88162d782fae7a030d1451b2c0edb21e12054e42` adds the directory to the full transfer, copies it as regular files, and checks each dependency before startup. I am retrying the audit with this fixed transfer.
Author
Owner

The full transfer now included the runtime libraries, but the preflight assertion rejected the ldd paths because it expected a trailing space after each filename. Commit 85c127fc12e7fb578cbfe6fda3ea7b80ad51c0f0 parses ldd into library-name/path pairs and compares the exact copied paths. This was a harness check defect; no API measurement ran. I am retrying from this head.

The full transfer now included the runtime libraries, but the preflight assertion rejected the `ldd` paths because it expected a trailing space after each filename. Commit `85c127fc12e7fb578cbfe6fda3ea7b80ad51c0f0` parses `ldd` into library-name/path pairs and compares the exact copied paths. This was a harness check defect; no API measurement ran. I am retrying from this head.
Author
Owner

The copied binary and both runtime libraries now pass remote ldd. Startup stderr identified the next issue: Error: "public URL must be HTTPS with a host (http is allowed only for localhost)". The VM server binds HTTP internally, but its configured public URL must use HTTPS for the non-localhost address. I will change that config and retry. No startup Index or API timings were produced. Head: 85c127fc12e7fb578cbfe6fda3ea7b80ad51c0f0.

The copied binary and both runtime libraries now pass remote `ldd`. Startup stderr identified the next issue: `Error: "public URL must be HTTPS with a host (http is allowed only for localhost)"`. The VM server binds HTTP internally, but its configured public URL must use HTTPS for the non-localhost address. I will change that config and retry. No startup Index or API timings were produced. Head: `85c127fc12e7fb578cbfe6fda3ea7b80ad51c0f0`.
Author
Owner

Commit b7172548c51b035cc757d3319c925984e4d8b5eb changes the non-localhost CALTERNAL_SERVER__PUBLIC_URL to HTTPS as required by server configuration. The internal listener and API probe remain HTTP. The startup diagnostic exposed this before indexing began, so it produced no timing data. Retrying from this head.

Commit `b7172548c51b035cc757d3319c925984e4d8b5eb` changes the non-localhost `CALTERNAL_SERVER__PUBLIC_URL` to HTTPS as required by server configuration. The internal listener and API probe remain HTTP. The startup diagnostic exposed this before indexing began, so it produced no timing data. Retrying from this head.
Author
Owner

Rerun checkpoint at head 199f444d257697fff58be1224026b673915aaf41.

The release server rejected the perf VM's numeric IP as a WebAuthn RP ID. I switched the public origin to 10.69.69.63.nip.io, which resolves to the perf VM, and send that declared HTTPS origin while connecting to the internal HTTP listener. The runner now uses the same origin for its authenticated owner and member sessions. Earlier launches stopped before timing began; no measurements are reported from them.

Next: validate startup and session writes, then append each read and bulk result to the CSV as it is measured. The audit remains time-boxed to 90 minutes of measurement.

Rerun checkpoint at head `199f444d257697fff58be1224026b673915aaf41`. The release server rejected the perf VM's numeric IP as a WebAuthn RP ID. I switched the public origin to `10.69.69.63.nip.io`, which resolves to the perf VM, and send that declared HTTPS origin while connecting to the internal HTTP listener. The runner now uses the same origin for its authenticated owner and member sessions. Earlier launches stopped before timing began; no measurements are reported from them. Next: validate startup and session writes, then append each read and bulk result to the CSV as it is measured. The audit remains time-boxed to 90 minutes of measurement.
Author
Owner

Index-startup checkpoint at head 6ac2bdc997b1387e5238fa6b17ecbfdae4dcca79 (perf lock held by this audit).

At 3m43s after process start the server used 389 MB RSS and about 24% CPU. The Index had 2,003 Notes and 1,000 Tasks, while the 5,000 Files and 24 Photos were not yet indexed. /readyz still refused connections, so startup indexing had not completed. The runner is polling the complete expected counts and will append the final elapsed time and counts to the CSV.

Index-startup checkpoint at head `6ac2bdc997b1387e5238fa6b17ecbfdae4dcca79` (perf lock held by this audit). At 3m43s after process start the server used 389 MB RSS and about 24% CPU. The Index had 2,003 Notes and 1,000 Tasks, while the 5,000 Files and 24 Photos were not yet indexed. `/readyz` still refused connections, so startup indexing had not completed. The runner is polling the complete expected counts and will append the final elapsed time and counts to the CSV.
Author
Owner

Index and fixture setup checkpoint at head 6ac2bdc997b1387e5238fa6b17ecbfdae4dcca79.

Direct Home seeding took 440.21 ms. The release server indexed all 2,003 Notes, 1,000 Tasks, 12 Logs, 5,000 Files and 24 Photos in 510,067 ms (8m30s) from process launch to complete counts. The CSV has the indexing result and counts before the API sweep began.

Capped API fixture setup took 3,502.81 ms. Shares (200), Notifications (12), and the Tus fixture (201) were created. Money confirmation returned status 0; Public Link returned 400; Calendar feed returned 403, so those fixtures are absent and affected contract routes will be reported as skipped or failed rather than as successful samples.

Index and fixture setup checkpoint at head `6ac2bdc997b1387e5238fa6b17ecbfdae4dcca79`. Direct Home seeding took 440.21 ms. The release server indexed all 2,003 Notes, 1,000 Tasks, 12 Logs, 5,000 Files and 24 Photos in 510,067 ms (8m30s) from process launch to complete counts. The CSV has the indexing result and counts before the API sweep began. Capped API fixture setup took 3,502.81 ms. Shares (200), Notifications (12), and the Tus fixture (201) were created. Money confirmation returned status 0; Public Link returned 400; Calendar feed returned 403, so those fixtures are absent and affected contract routes will be reported as skipped or failed rather than as successful samples.
Author
Owner

Read-phase checkpoint at head fcd648e742df8e3ee07f44911a39444348352424 (runner revision 199f444d257697fff58be1224026b673915aaf41). The release server ran on the perf VM under perf-run. The sweep sampled 112 of 185 GET/HEAD contract operations and skipped 73. Each sample and each route summary is already flushed to target/tmp/api-audit-1374/timings-final.csv. Bulk visibility measurements and query plans are pending.

Read rank Operation Route n p95 max p50 bytes returned rows status
1 by_day GET /api/v1/notes/tasks/day 20 137.00 ms 138.02 ms 20,189,645 43,804 200
2 calendar_range GET /api/v1/calendar/range 20 95.34 ms 96.03 ms 438,425 92 200
3 calendar_year GET /api/v1/calendar/year 20 92.19 ms 96.54 ms 76,636 365 200
4 notes_journal_get_entry GET /api/v1/notes/journal/entries/{block_id} 20 86.48 ms 86.64 ms 62 1 404; invalid fixture block ID
5 files_quota GET /api/v1/files/quota 20 65.47 ms 65.74 ms 66 1 200
6 search GET /api/v1/search 20 64.06 ms 65.08 ms 87,885 300 200
7 files_recent GET /api/v1/files/recent 20 49.73 ms 49.95 ms 39,210 100 200
8 admin_list_jobs GET /api/v1/admin/jobs 20 44.23 ms 58.81 ms 25,269 1 200
9 photos_timeline_buckets GET /api/v1/photos/timeline/buckets 20 38.54 ms 46.40 ms 53 1 200
10 list_file_assignments GET /api/v1/tags/items 20 37.76 ms 51.70 ms 37 1 200

Read ranking uses the 50 ms target specified in this job. The 404 Journal row is a fixture miss, not a successful data-read result. The complete report will include every sampled route, bulk results, query plans and source causes.

Read-phase checkpoint at head `fcd648e742df8e3ee07f44911a39444348352424` (runner revision `199f444d257697fff58be1224026b673915aaf41`). The release server ran on the perf VM under `perf-run`. The sweep sampled 112 of 185 GET/HEAD contract operations and skipped 73. Each sample and each route summary is already flushed to `target/tmp/api-audit-1374/timings-final.csv`. Bulk visibility measurements and query plans are pending. | Read rank | Operation | Route | n | p95 | max | p50 bytes | returned rows | status | | ---: | --- | --- | ---: | ---: | ---: | ---: | ---: | --- | | 1 | `by_day` | `GET /api/v1/notes/tasks/day` | 20 | 137.00 ms | 138.02 ms | 20,189,645 | 43,804 | 200 | | 2 | `calendar_range` | `GET /api/v1/calendar/range` | 20 | 95.34 ms | 96.03 ms | 438,425 | 92 | 200 | | 3 | `calendar_year` | `GET /api/v1/calendar/year` | 20 | 92.19 ms | 96.54 ms | 76,636 | 365 | 200 | | 4 | `notes_journal_get_entry` | `GET /api/v1/notes/journal/entries/{block_id}` | 20 | 86.48 ms | 86.64 ms | 62 | 1 | 404; invalid fixture block ID | | 5 | `files_quota` | `GET /api/v1/files/quota` | 20 | 65.47 ms | 65.74 ms | 66 | 1 | 200 | | 6 | `search` | `GET /api/v1/search` | 20 | 64.06 ms | 65.08 ms | 87,885 | 300 | 200 | | 7 | `files_recent` | `GET /api/v1/files/recent` | 20 | 49.73 ms | 49.95 ms | 39,210 | 100 | 200 | | 8 | `admin_list_jobs` | `GET /api/v1/admin/jobs` | 20 | 44.23 ms | 58.81 ms | 25,269 | 1 | 200 | | 9 | `photos_timeline_buckets` | `GET /api/v1/photos/timeline/buckets` | 20 | 38.54 ms | 46.40 ms | 53 | 1 | 200 | | 10 | `list_file_assignments` | `GET /api/v1/tags/items` | 20 | 37.76 ms | 51.70 ms | 37 | 1 | 200 | Read ranking uses the 50 ms target specified in this job. The 404 Journal row is a fixture miss, not a successful data-read result. The complete report will include every sampled route, bulk results, query plans and source causes.
Author
Owner

Rerun checkpoint. Branch head: 94b056bfe9b49d24aee6da2412a88dd9f955f935.

The perf VM read sweep sampled 112 of 185 OpenAPI GET/HEAD operations, 20 requests each, and skipped 73. This table ranks the sampled routes by p95 against the 50 ms target. The full per-sample CSV is committed at docs/perf/2026-10-08-1374-api-audit.csv.

Rank Route p50 / p95 / max ms Bytes Rows touched Status
1 GET /api/v1/notes/tasks/day 111.77 / 137.00 / 138.02 20,189,645 43,804 200 × 20
2 GET /api/v1/calendar/range 78.89 / 95.34 / 96.03 438,425 92 200 × 20
3 GET /api/v1/calendar/year 73.38 / 92.19 / 96.54 76,636 365 200 × 20
4 GET /api/v1/notes/journal/entries/{block_id} 58.77 / 86.48 / 86.64 62 1 404 × 20; invalid fixture
5 GET /api/v1/files/quota 48.15 / 65.47 / 65.74 66 1 200 × 20
6 GET /api/v1/search 59.70 / 64.06 / 65.08 87,885 300 200 × 20
7 GET /api/v1/files/recent 38.22 / 49.73 / 49.95 39,210 100 200 × 20
8 GET /api/v1/admin/jobs 40.55 / 44.23 / 58.81 25,269 1 200 × 20
9 GET /api/v1/photos/timeline/buckets 29.87 / 38.54 / 46.40 53 1 200 × 20
10 GET /api/v1/tags/items 28.29 / 37.76 / 51.70 37 1 200 × 20

The Journal row used an invalid Block ID and is not a successful-read result. Repeated Auth reads also returned 429; the CSV keeps all statuses. rows touched is a response-row proxy, not the Index rows scanned.

Initial source attribution: crates/plugins/notes/src/tasks_api.rs::by_day returned 43,804 Task-day rows (20.2 MB); Calendar calls crates/plugins/calendar/src/view.rs::range / ::year and project_days; Files quota calls crates/plugins/files/src/uploads.rs::quota then crates/calternal-fs/src/quota.rs::recompute_quota; Search calls crates/calternal-server/src/main.rs::search. Supplemental SQL plans are being captured under the audit lock after bulk measurements.

Bulk measurements are in progress under perf-run calternal apiaudit2-bulk. I will append the bulk visibility ranks and final worst ten after that phase completes.

Rerun checkpoint. Branch head: `94b056bfe9b49d24aee6da2412a88dd9f955f935`. The perf VM read sweep sampled 112 of 185 OpenAPI GET/HEAD operations, 20 requests each, and skipped 73. This table ranks the sampled routes by p95 against the 50 ms target. The full per-sample CSV is committed at `docs/perf/2026-10-08-1374-api-audit.csv`. | Rank | Route | p50 / p95 / max ms | Bytes | Rows touched | Status | | ---: | --- | ---: | ---: | ---: | --- | | 1 | `GET /api/v1/notes/tasks/day` | 111.77 / 137.00 / 138.02 | 20,189,645 | 43,804 | 200 × 20 | | 2 | `GET /api/v1/calendar/range` | 78.89 / 95.34 / 96.03 | 438,425 | 92 | 200 × 20 | | 3 | `GET /api/v1/calendar/year` | 73.38 / 92.19 / 96.54 | 76,636 | 365 | 200 × 20 | | 4 | `GET /api/v1/notes/journal/entries/{block_id}` | 58.77 / 86.48 / 86.64 | 62 | 1 | 404 × 20; invalid fixture | | 5 | `GET /api/v1/files/quota` | 48.15 / 65.47 / 65.74 | 66 | 1 | 200 × 20 | | 6 | `GET /api/v1/search` | 59.70 / 64.06 / 65.08 | 87,885 | 300 | 200 × 20 | | 7 | `GET /api/v1/files/recent` | 38.22 / 49.73 / 49.95 | 39,210 | 100 | 200 × 20 | | 8 | `GET /api/v1/admin/jobs` | 40.55 / 44.23 / 58.81 | 25,269 | 1 | 200 × 20 | | 9 | `GET /api/v1/photos/timeline/buckets` | 29.87 / 38.54 / 46.40 | 53 | 1 | 200 × 20 | | 10 | `GET /api/v1/tags/items` | 28.29 / 37.76 / 51.70 | 37 | 1 | 200 × 20 | The Journal row used an invalid Block ID and is not a successful-read result. Repeated Auth reads also returned 429; the CSV keeps all statuses. `rows touched` is a response-row proxy, not the Index rows scanned. Initial source attribution: `crates/plugins/notes/src/tasks_api.rs::by_day` returned 43,804 Task-day rows (20.2 MB); Calendar calls `crates/plugins/calendar/src/view.rs::range` / `::year` and `project_days`; Files quota calls `crates/plugins/files/src/uploads.rs::quota` then `crates/calternal-fs/src/quota.rs::recompute_quota`; Search calls `crates/calternal-server/src/main.rs::search`. Supplemental SQL plans are being captured under the audit lock after bulk measurements. Bulk measurements are in progress under `perf-run calternal apiaudit2-bulk`. I will append the bulk visibility ranks and final worst ten after that phase completes.
Author
Owner

Rerun complete. Branch: job/apiaudit-1374. Head: 6fff284d44e902523c6c718b7bdb538f0fa00c2b.

Perf VM release server d395b6e25 (matching web build d395b6e25da20d8c67b8b9fc1a593b813939c8a7). File seed took 440.21 ms; Index startup took 510,067 ms for 2,003 Notes, 1,000 Tasks, 12 Logs, 5,000 Files and 24 Photos. Read and bulk measurements took 2,962,236.89 ms total, within the 90-minute budget. Results append to docs/perf/2026-10-08-1374-api-audit.csv; SQL plans and worst-ten evidence are in docs/perf/2026-10-08-1374-api-audit-plans.json.

Read routes: 112 fixture-backed GET/HEAD operations, 20 samples each, sorted by p95 against 50 ms. The CSV includes every rank and sample; 73 contract operations were skipped with per-route reasons.

Rank Read route p95 ms Status
1 GET /api/v1/notes/tasks/day 137.00 200 × 20
2 GET /api/v1/calendar/range 95.34 200 × 20
3 GET /api/v1/calendar/year 92.19 200 × 20
4 GET /api/v1/notes/journal/entries/{block_id} 86.48 404 × 20; invalid fixture
5 GET /api/v1/files/quota 65.47 200 × 20
6 GET /api/v1/search 64.06 200 × 20
7 GET /api/v1/files/recent 49.73 200 × 20
8 GET /api/v1/admin/jobs 44.23 200 × 20
9 GET /api/v1/photos/timeline/buckets 38.54 200 × 20
10 GET /api/v1/tags/items 37.76 200 × 20

Worst ten bulk visibility results, sorted by elapsed milliseconds (target 500 ms; lower bounds are censored, not exact times):

Rank Operation Visible ms Result Source (file:function)
1 Complete 1,000 Tasks 1,347,186.57 200 × 1,000 crates/plugins/notes/src/tasks_api.rs::tick
2 Undo completion of 1,000 Tasks ≥600,374.06 200 × 166; 500 × 834 crates/plugins/notes/src/tasks_api.rs::tick
3 Rename Tag across 100 Notes ≥120,186.76 200; rewrite completed, state not observed crates/calternal-tags/src/lib.rs::rename_tag
4 Undo Tag rename across 100 Notes ≥120,149.34 200; rewrite completed, state not observed crates/calternal-tags/src/lib.rs::undo_rewrite
5 Unshare Folder ≥120,018.12 204; visibility probes mostly status 0 crates/plugins/files/src/shares.rs::revoke
6 Re-tag 100 Files 23,715.12 200 × 100 crates/calternal-tags/src/lib.rs::assign_tags
7 Rename Folder Undo, 1,000 children 1,257.50 204 crates/plugins/files/src/lib.rs::rename
8 Move Folder, 1,000 children 831.21 204 crates/plugins/files/src/lib.rs::move_paths
9 Rename Folder, 1,000 children 572.91 204 crates/plugins/files/src/lib.rs::rename
10 Move Folder Undo, 1,000 children 280.84 204 crates/plugins/files/src/lib.rs::move_paths

Plans for those routes are captured in the JSON. The Task Undo 5xx finding is filed as #1446. The Mark-all-Notifications operation was visible in 189.33 ms (HTTP 204). Delete-to-Trash returned transport status 0 for both 500-item requests after 240,018.44 ms; restore operations were skipped because the Trash fixture did not settle. Hide/Unhide were invalid HTTP 400 samples from the runner version loaded at start.

The 2026-10-08 report is docs/perf/2026-10-08-1374-api-audit.md. node --check bench/api-audit-1374.mjs and git diff --check exited 0 with no output. Rust gates and bun run check were not run because no Rust or web code changed. cargo clean output: Removed 1 file, 356B total; apps/web/build was removed. No push, deploy, merge or issue close was performed.

Rerun complete. Branch: `job/apiaudit-1374`. Head: `6fff284d44e902523c6c718b7bdb538f0fa00c2b`. Perf VM release server `d395b6e25` (matching web build `d395b6e25da20d8c67b8b9fc1a593b813939c8a7`). File seed took 440.21 ms; Index startup took 510,067 ms for 2,003 Notes, 1,000 Tasks, 12 Logs, 5,000 Files and 24 Photos. Read and bulk measurements took 2,962,236.89 ms total, within the 90-minute budget. Results append to `docs/perf/2026-10-08-1374-api-audit.csv`; SQL plans and worst-ten evidence are in `docs/perf/2026-10-08-1374-api-audit-plans.json`. Read routes: 112 fixture-backed GET/HEAD operations, 20 samples each, sorted by p95 against 50 ms. The CSV includes every rank and sample; 73 contract operations were skipped with per-route reasons. | Rank | Read route | p95 ms | Status | | ---: | --- | ---: | --- | | 1 | `GET /api/v1/notes/tasks/day` | 137.00 | 200 × 20 | | 2 | `GET /api/v1/calendar/range` | 95.34 | 200 × 20 | | 3 | `GET /api/v1/calendar/year` | 92.19 | 200 × 20 | | 4 | `GET /api/v1/notes/journal/entries/{block_id}` | 86.48 | 404 × 20; invalid fixture | | 5 | `GET /api/v1/files/quota` | 65.47 | 200 × 20 | | 6 | `GET /api/v1/search` | 64.06 | 200 × 20 | | 7 | `GET /api/v1/files/recent` | 49.73 | 200 × 20 | | 8 | `GET /api/v1/admin/jobs` | 44.23 | 200 × 20 | | 9 | `GET /api/v1/photos/timeline/buckets` | 38.54 | 200 × 20 | | 10 | `GET /api/v1/tags/items` | 37.76 | 200 × 20 | Worst ten bulk visibility results, sorted by elapsed milliseconds (target 500 ms; lower bounds are censored, not exact times): | Rank | Operation | Visible ms | Result | Source (`file:function`) | | ---: | --- | ---: | --- | --- | | 1 | Complete 1,000 Tasks | 1,347,186.57 | 200 × 1,000 | `crates/plugins/notes/src/tasks_api.rs::tick` | | 2 | Undo completion of 1,000 Tasks | ≥600,374.06 | 200 × 166; 500 × 834 | `crates/plugins/notes/src/tasks_api.rs::tick` | | 3 | Rename Tag across 100 Notes | ≥120,186.76 | 200; rewrite completed, state not observed | `crates/calternal-tags/src/lib.rs::rename_tag` | | 4 | Undo Tag rename across 100 Notes | ≥120,149.34 | 200; rewrite completed, state not observed | `crates/calternal-tags/src/lib.rs::undo_rewrite` | | 5 | Unshare Folder | ≥120,018.12 | 204; visibility probes mostly status 0 | `crates/plugins/files/src/shares.rs::revoke` | | 6 | Re-tag 100 Files | 23,715.12 | 200 × 100 | `crates/calternal-tags/src/lib.rs::assign_tags` | | 7 | Rename Folder Undo, 1,000 children | 1,257.50 | 204 | `crates/plugins/files/src/lib.rs::rename` | | 8 | Move Folder, 1,000 children | 831.21 | 204 | `crates/plugins/files/src/lib.rs::move_paths` | | 9 | Rename Folder, 1,000 children | 572.91 | 204 | `crates/plugins/files/src/lib.rs::rename` | | 10 | Move Folder Undo, 1,000 children | 280.84 | 204 | `crates/plugins/files/src/lib.rs::move_paths` | Plans for those routes are captured in the JSON. The Task Undo 5xx finding is filed as #1446. The Mark-all-Notifications operation was visible in 189.33 ms (HTTP 204). Delete-to-Trash returned transport status 0 for both 500-item requests after 240,018.44 ms; restore operations were skipped because the Trash fixture did not settle. Hide/Unhide were invalid HTTP 400 samples from the runner version loaded at start. The 2026-10-08 report is `docs/perf/2026-10-08-1374-api-audit.md`. `node --check bench/api-audit-1374.mjs` and `git diff --check` exited 0 with no output. Rust gates and `bun run check` were not run because no Rust or web code changed. `cargo clean` output: `Removed 1 file, 356B total`; `apps/web/build` was removed. No push, deploy, merge or issue close was performed.
Author
Owner

Deployed to calternal.cloud in merge round 35a (build cc1af3c12, live 2026-10-09 00:12 IST). Closing.

Deployed to calternal.cloud in merge round 35a (build cc1af3c12, live 2026-10-09 00:12 IST). Closing.
kayg closed this issue 2026-10-08 18:41:19 +00:00
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#1374
No description provided.