diag(ai-gateway): measure whether pool slots are leaked - #5107
Conversation
The instrumentation from #5098 established that pool acquisition dominates /api/internal/usage/record: idle == 0 on 96-98% of sampled requests with up to 245 queued against max 10, while PostgreSQL reports zero active queries and Supavisor zero waiting clients. Connections are checked out without doing work, and there are two explanations that call for opposite fixes. Either Fluid compute packs high concurrency onto few instances and ten connections is simply too few, or slots are leaked and never return. drizzle-orm 0.45.2 issues BEGIN outside its try/finally, so a failed BEGIN never reaches release() and burns that slot for the life of the process; ten of those kill an instance permanently. If that is what is happening, raising max postpones and hides it, and max is a single module-level constant shared by every route in both Vercel projects whose comment records that raising it previously exhausted Supabase's connection limit. The arithmetic is what makes this worth measuring rather than assuming: at ~47 req/s with Frankfurt-local statements of 2-10ms, roughly 5 connections are needed, not 245 queued. The discriminator is the low-water mark of checked-out connections. A healthy pool returns to zero checked out whenever the instance goes quiet, and idleTimeoutMillis of 5s then closes the idle clients. A leaked client is never returned to _idle, so it counts as checked out forever and the low-water mark cannot fall below the number of leaks. A low-water mark rather than an instantaneous reading because this pool is shared with every other route on the instance: one quiet moment resets it, so unrelated traffic cannot inflate it. Adds, all read-only counters updated on pg-pool events, with no queries and no timers: - acquires/releases/connects/removes, plus outstanding as a cross-check that should track pool.totalCount - pool.idleCount - min_checked_out and max_checked_out - begin_failures, counted where the retry loop already inspects the error. Matching the message is safe only for BEGIN, which takes no parameters and so carries no prompt text or client IP - ms_since_last_request and checked_out_at_entry, read before the request acquires anything Emission now also triggers on the first request after 5s of instance quiet. Those requests are fast, so the duration threshold would never surface them, yet they are the only moment a leaked slot is distinguishable from a busy one. Counters do not attach under NODE_ENV=test, matching how drizzle.ts already treats the test pool.
| const timer = createPhaseTimer(); | ||
| // Read before this request acquires anything: on an instance that has been quiet | ||
| // longer than `idleTimeoutMillis`, anything still checked out belongs to nobody. | ||
| const msSinceLastRequest = noteRequestStart(); |
There was a problem hiding this comment.
SUGGESTION: A 400 response consumes the quiet-instance observation point without emitting it
noteRequestStart() runs for every authorized request, but a request that fails schema validation returns 400 before reportTiming is ever called. If the first request after a >=5s quiet period is a 400, it resets lastRequestAtMs, so the next (fast) request no longer meets QUIET_INSTANCE_MS and the one moment a leaked slot is distinguishable from a busy one is lost. Rare on this internal endpoint, but if these observation points matter, consider updating the clock only on requests that can actually emit (e.g. moving the call after validation, or resetting it on the 400 path).
Reply with @kilocode-bot fix it to have Kilo Code address this issue.
Code Review SummaryStatus: 1 Issue Found | Recommendation: Address before merge Overview
Issue Details (click to expand)SUGGESTION
Files Reviewed (6 files)
Fix these issues in Kilo Cloud Reviewed by kimi-k3 · Input: 86.1K · Output: 22.6K · Cached: 951.3K Review guidance: REVIEW.md from base branch |
| if (process.env.NODE_ENV !== 'test') { | ||
| pool.on('acquire', () => { | ||
| counters.acquires++; | ||
| sampleCheckedOut(); | ||
| }); | ||
| pool.on('release', () => { | ||
| counters.releases++; | ||
| sampleCheckedOut(); | ||
| }); | ||
| pool.on('connect', () => { | ||
| counters.connects++; | ||
| }); | ||
| pool.on('remove', () => { | ||
| counters.removes++; | ||
| sampleCheckedOut(); | ||
| }); | ||
| } |
There was a problem hiding this comment.
Probably not, but do we need something to teardown these listeners? Perhaps if drizzle ever recreates the pool?
Summary
Item 2 of the follow-ups from #5098. This is a measurement, not a fix — it exists to decide between two explanations that call for opposite remedies.
#5098's instrumentation established that pool acquisition dominates
/api/internal/usage/record:idle == 0on 96–98% of sampled requests with up to 245 queued againstmax: 10, while PostgreSQL reports zero active queries and Supavisor reportsclient_waiting: 0withpool_size320 againstserver_active67. Connections are checked out without doing work. Either:BEGINoutside itstry/finally, so a failedBEGINnever reaches therelease()in thefinallyand burns that slot for the life of the process. Ten of those kill an instance permanently. Fix: release on a failedBEGIN.Getting this wrong is expensive in both directions. If it's a leak, raising
maxpostpones and conceals it — andmaxatdrizzle.ts:93is a single module-level constant shared by every route in both Vercel projects, whose inline comment records that raising it previously exhausted Supabase's connection limit across ~2,200 instances.The arithmetic is what makes this worth measuring rather than assuming: at ~47 req/s with Frankfurt-local statements of 2–10 ms, you need roughly 5 connections, not 245 queued.
The discriminator
The low-water mark of checked-out connections. A healthy pool returns to zero checked out whenever the instance goes quiet, and
idleTimeoutMillisof 5 s then closes the idle clients. A leaked client is never returned to_idle, so it counts as checked out forever and the low-water mark cannot fall below the number of leaks.A low-water mark rather than an instantaneous reading, because this pool is shared with every other route on the instance —
/api/profile,/api/defaultsand the rest. One quiet moment resets it, so unrelated concurrent traffic cannot inflate it. An instantaneouschecked_out > 0proves nothing; a floor that climbs does.What it adds
All read-only counters updated on
pg-poolevents. No queries, no timers.acquires/releases/connects/removes, plusoutstandingas a cross-check that should trackpool.totalCount - pool.idleCount. A persistent divergence means the accounting is wrong and nothing else should be trusted.min_checked_outandmax_checked_out.begin_failures— counted where the retry loop already inspects the error. Under the drizzle bug each one is exactly one leaked slot, which makes it directly comparable tomin_checked_out. Matching on the message is safe only forBEGIN: it takes no parameters, so unlike every other statement in this path the message carries no prompt text or client IP.ms_since_last_requestandchecked_out_at_entry, read before the request acquires anything.Emission now also triggers on the first request after 5 s of instance quiet. Those requests are fast, so the duration threshold would never surface them — yet they are the only moment a leaked slot is distinguishable from a busy one.
Counters do not attach under
NODE_ENV=test, matching howdrizzle.tsalready special-cases the test pool.Verification
Automated:
tsgo --noEmit -p apps/web/tsconfig.jsonclean;./scripts/lint-all.sh0 warnings 0 errors; 17 new probe tests and 6 new emission/clock tests; 923 passing across 70 suites insrc/lib/ai-gateway+src/lib/drizzle.test.ts+src/lib/db-pool-leak-probe.test.ts+src/app/api/internal;pnpm formatandgit diff --checkclean. Targeted verification, notpnpm validate.Manual: none, and it cannot be meaningful here. The behaviour under investigation only appears under production concurrency; locally the pool never exceeds a couple of connections, so a local run would show
min_checked_out: 0whether or not the bug exists. The unit tests cover the classifier and the arithmetic; only production can answer the question.Visual Changes
N/A
Reviewer Notes
How to read the result. The verdict is a comparison, not a threshold:
min_checked_outat 0 andchecked_out_at_entrynear 0 on quiet instances → no leak. The pool is genuinely busy, and sizing (ideally a dedicated pool, to bound the blast radius) is the right next step.min_checked_outabove 0 and climbing with uptime, trackingbegin_failures→ leak confirmed. The fix is wrappingdb.transactionso a failedBEGINreleases its client, not more connections.min_checked_outabove 0 butbegin_failuresat 0 → a leak from some other path, and I would want to know that before touching anything.Things worth challenging:
min_checked_outis process-lifetime and never reset, so on a long-lived instance a single early quiet moment pins it at 0 forever and could mask a leak that started later. Comparing it againstchecked_out_at_entryon quiet requests is the mitigation, but a windowed low-water mark would be strictly better if this proves inconclusive.begin_failuresis only incremented on the usage-write path. ABEGINfailure anywhere else in the process leaks a slot without being counted, which is exactly the third case above.route.tsin the same import block as perf(ai-gateway): drop the usage-record dedupe pre-check #5105, so expect a trivial conflict depending on merge order. Both changes are independent; either can land first.