Discover first-page stage profiling

The bounded Railway testing run passed all eight phases and 96 HTTP checks, with 1,890 SQL calls and zero SQL errors. It used the same application code as the earlier origin probe; this run changed the test instrumentation and audit implementation. It establishes no application speedup, production capacity, or recommendation-quality uplift.

Identity and reproduction

• Application source: 5336d2f23da54e543045e007ce60fc50becd02d2 (report-only changes after tested code b4c32d1f1), Node 22.23.2.
• Frozen context: ignored .local-artifacts/full-origin-context-profile-02.
• Report: ignored .local-artifacts/profile-controller-result.json, SHA-256 8576e707ba66c99f45649e311ca29bf9a3d2541979cda4d286e8ca8678091eba.
• Analysis: .local-artifacts/profile-origin-analysis.json, generated by profile-origin-analyze.mjs; original probe/result remain unchanged.
• Run: d16ab18b472d21e31c9b6a4ebb0168c9; temporary service 4e2a1061-b80f-4b83-bb49-567bd77bccee, deployment 138f201a-cf6d-4242-bc3a-504deb007b6d.
• Synthetic-only database codex_discovery_df81f74d35414e6d, restricted role codex_origin_df81f74d35414e6d, separate testing Redis instance.

Thirty-one offline tests passed without skips before traffic, including actual pg-pool queued-checkout attribution, overlapping span unions, failure handling, complete stacked callback receiver forwarding, bounded UTF-8 profile headers, and existing ownership/memory/deadline guards. Both import checks passed without network access. Independent review found two harness issues (header bound and inherited callback receiver loss); both were reproduced, fixed, and re-reviewed.

The final report exceeded Railway's individual log-message size and was split into two messages. The collector reconstructed only the known result envelope, with a 1-MiB/32-chunk ceiling and exact run-ID validation before saving it.

Observations

Each concurrency level ran two rounds. First-page and continuation counts below are 2, 8, and 16 respectively. At these sample sizes the split p95 is the maximum; these are descriptive diagnostics, not stable tail-latency estimates.

Concurrent actors	First page p50 / p95 (ms)	Continuation p50 / p95 (ms)
1	349.17 / 371.60	117.79 / 121.85
4	493.20 / 547.21	152.34 / 177.17
8	873.18 / 963.44	228.13 / 265.92

The following are per-request interval unions, summarized across first-page requests. Categories overlap; do not add or subtract their percentiles.

Stage	1 actor p50 / p95 (ms)	4 actors p50 / p95 (ms)	8 actors p50 / p95 (ms)
PostgreSQL checkout	5.81 / 5.98	76.97 / 143.87	285.97 / 381.34
Client SQL execution	284.04 / 298.07	341.86 / 358.25	448.96 / 544.28
Catalog-classified SQL	242.43 / 260.67	285.37 / 305.51	326.98 / 397.77
Redis Lua execution	15.02 / 15.19	18.96 / 42.40	38.07 / 112.09
Audit queue	0.01 / 0.01	0.01 / 19.87	53.45 / 83.85
Audit execution	6.76 / 7.48	23.64 / 45.14	15.43 / 62.33
Unattributed request time	33.51 / 41.27	35.48 / 37.91	34.38 / 46.99

First pages completed 13 catalog-classified queries; continuations completed two. The eight-connection application pool reached 60 pending acquisitions. Checkout includes queueing, connection creation and verification; it is not exclusively queue wait. SQL groups are fixed heuristic categories, not exact function names. No SQL text, arguments, credentials, or raw errors were recorded by the profiler.

Every load-request header had two unfinished spans at response time. All spans finished before final reporting (pending = 0). Header unions describe completed work at header capture; they are not exhaustive attribution of work completing after the response. Unattributed wall time must not be called CPU time. Phase CPU/event-loop observations include both application and harness work.

Audit overhead remains included in HTTP latency. The new harness pipelines string length checks and audits only active candidate keys, while keeping all historical keys for final cleanup. Consequently comparison against the previous run is confounded by harness changes and environmental variation. No pool limit, query, ranking, application cache, or encoding changed.

Correctness and cleanup

• Traversed all 713 eligible synthetic story families in 15 pages, with zero duplicate IDs/families or missing stories; committed retry matched and a stolen cursor was rejected.
• Confirmed save/guest-link and impression idempotency passed. Saving two families left exactly 711 eligible families across 15 pages, including exclusion of a translated sibling. Real stored Better Auth sessions were used.
• Sampled Redis peak: 7,345,727 bytes; peak aggregate payload 6,988,226 bytes; reservation peak 6,988,194 bytes. These are namespace totals, not one response.
• Runtime verified all 69 tracked keys absent. Parent cleanup independently scanned the exact owned namespace and found it empty, removed the temporary service/database/role, and verified their absence with zero active database connections. No forced disconnects or production writes occurred.

Decision

Catalog retrieval is the largest observed first-page component and checkout delay grows under concurrency. This justifies examining repeated recall queries and their execution plans before considering a larger pool. It does not identify one specific slow SQL statement or prove that batching/caching will improve the full request. Any application optimization needs result-parity tests and a matched before/after probe; a pool increase alone could move contention into PostgreSQL.

The workload remains synthetic, single-process, four real Hono modules over loopback HTTP, using Railway testing PostgreSQL rather than production Neon. General Redis, PostHog and background import timers were disabled. It does not exercise the public proxy, actual catalog sizes/distribution, production replicas, autoscaling, or all application traffic. The production topology/capacity and ClickPipe receipt/erasure gates remain open. Experimental ranking remains disabled.