feat: measure the wait for a pool connection, and count pool checkout timeouts

[AlexeyShalaev]

Summary

Two defects in the pool metrics, both reported in #26 and both reproduced before anything
was written.

postgres_db_connection_timeouts_total did not count pool checkout timeouts. It was
fed only from the engine's handle_error listener. A QueuePool checkout timeout is
raised by pool.connect() before any DBAPI call, so it never reaches that listener — the
one timeout a pool actually produces under load was the one the counter did not count.

postgres_db_connection_checkout_duration_seconds measures held time, not wait. It is
the interval between the checkout and checkin events: how long a caller held a
connection, which is query duration seen from the pool. Useful, but its name says checkout
and the guide read it as the time a caller waited. The wait — the number that predicts a
pool outage — was not exposed at all.

What changed

Series	Status
postgres_db_connection_checkout_wait_seconds	new histogram: time spent inside pool.connect() before a connection is handed out — the queue wait, plus the pre-ping and the connect handshake when the pool has to grow. Buckets run to 30 s, the default pool_timeout, so a saturated pool fills the top buckets instead of collapsing into +Inf
postgres_db_connection_held_duration_seconds	new name for the number the old histogram always carried
postgres_db_connection_checkout_duration_seconds	deprecated. Still published, with the same values, so existing dashboards keep working. Removed in a future release
postgres_db_connection_timeouts_total	changed meaning: it now also counts pool checkout timeouts, which is what its description always claimed. It can only go up relative to before — an alert on it will fire in cases where it previously stayed silent, which is the point

Nothing is removed and no signature changes, so this is a feat: — a minor bump, which is
what a metric changing meaning warrants.

Design, and what I rejected

SQLAlchemy fires no event when a checkout is requested, only when one succeeds, so the
wait cannot come from a listener. It has to be timed inside the pool.

instrument_pool_class(pool_class, metrics) (in session.manager, beside attach_metrics)
returns a subclass that times Pool.connect(). That is the right hook:

• it runs exactly once per checkout, and is what Engine.raw_connection() calls for sync
  and async engines alike;
• the pool's TimeoutError passes through it exactly once;
• under AsyncAdaptedQueuePool the queue wait is an await_only inside that call, so a
  perf_counter pair around super().connect() in the greenlet spans the whole suspension
  and measures the time the caller really spent waiting.

Rejected: overriding _do_get. QueuePool recurses into it when the non-blocking get
comes back empty and the race for an overflow slot is lost — precisely the contended case
this metric exists for. It would observe the same wait twice and count one timeout as two.

Rejected: timing session.connection() in get_session. It misses everything that goes
through session_maker — the unit of work, both DI containers — and engine.connect().

The recorder lives on the class, which is what makes a pool produced by recreate() after
dispose() keep recording. AsyncSessionManager wraps whatever resolve_pool_class
returned before building the engine, so registered custom pools and the six built-ins are
covered without touching callers.

The capability is a new narrow CheckoutWaitRecorder, deliberately not part of
PostgresMetricsProtocol: a hand-written implementation from the guide stays valid and
simply publishes no wait series. attach_metrics now logs a warning when the metrics object
records the wait but the engine's pool was not built for it, so a self-built engine does not
end up with an empty histogram nobody notices.

Verification

make check and make test (the repo's full gate, 90% coverage floor):

uv run ruff check .          All checks passed!
uv run ruff format --check . 95 files already formatted
uv run mypy ...              Success: no issues found in 44 source files
626 passed — Required test coverage of 90% reached. Total coverage: 93.75%

Tests that fail on master and pass here — tests/integration/test_metrics_integration.py,
against a PostgreSQL 17 container:

test__pool_metrics__pool_runs_out__counts_the_timeout_and_measures_the_wait
    E   ValueError: min() iterable argument is empty      # no wait was recorded at all
test__postgres_metrics__pool_runs_out__moves_the_series_a_dashboard_scrapes
    E   assert 0.0 == 1.0                                 # timeouts_total through a timeout

The reporter's own lab, run unmodified against this branch — timeouts_total now tracks
the application's own count of sqlalchemy.exc.TimeoutError exactly, where it stayed at 0
before:

   3.0 s  in_use=4/4  checkouts/s=  76  checkout wait=   53 ms  timeouts_total=0 errors_total=0  requests failed on pool timeout=0
  ... the database slows down: queries take 1.0 s instead of 0.05 s
   5.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1003 ms  timeouts_total=1 errors_total=0  requests failed on pool timeout=1
   6.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1003 ms  timeouts_total=1 errors_total=0  requests failed on pool timeout=1
   7.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1003 ms  timeouts_total=2 errors_total=0  requests failed on pool timeout=2
   8.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1004 ms  timeouts_total=2 errors_total=0  requests failed on pool timeout=2

Its checkout wait column still shows held time because the script reads the deprecated
series by name — which is exactly the confusion the rename fixes. The same run with the
column pointed at …_checkout_wait_seconds, and a second column for
…_held_duration_seconds:

   3.0 s  in_use=4/4  checkouts/s=  76  wait=   54 ms  held=   52 ms  timeouts_total=0 errors_total=0  requests failed on pool timeout=0
  ... the database slows down: queries take 1.0 s instead of 0.05 s
   5.0 s  in_use=4/4  checkouts/s=  12  wait=  669 ms  held= 1004 ms  timeouts_total=2 errors_total=0  requests failed on pool timeout=2
   6.0 s  in_use=4/4  checkouts/s=   8  wait=  980 ms  held= 1002 ms  timeouts_total=2 errors_total=0  requests failed on pool timeout=2
   7.0 s  in_use=4/4  checkouts/s=  12  wait=  668 ms  held= 1003 ms  timeouts_total=4 errors_total=0  requests failed on pool timeout=4
   8.0 s  in_use=4/4  checkouts/s=   8  wait=  981 ms  held= 1003 ms  timeouts_total=4 errors_total=0  requests failed on pool timeout=4

held is the query duration, 1 s. wait is the queue wait, bounded above by the 1 s
pool_timeout — the callers that give up contribute exactly 1000 ms, the ones that are
served waited less. Before the slowdown the two coincide, because a pool of four with eight
workers is exactly saturated and each caller waits about one query's worth.

Behaviour for anyone who never had this problem is unchanged: no metric was removed or
renamed in place, record_checkout keeps its name and its meaning, PostgresMetricsProtocol
keeps its three methods, and a metrics object without record_checkout_wait gets exactly
what it got before.

Type of change

• Bug fix
• New feature
• Breaking change
• Documentation update
• Refactoring / internal

Checklist

• Tests added or updated
• make check passes locally (ruff + mypy)
• CHANGELOG.md updated under [Unreleased] — n/a, the changelog is generated by
  release-please from the conventional commit
• Documentation updated (if the public API changed), docs/agents.md included

Related issues

Closes #26

[codecov]

Codecov Report

❌ Patch coverage is 90.90909% with 3 lines in your changes missing coverage. Please review.

Files with missing lines	Patch %	Lines
sqlalchemy_foundation_kit/session/manager.py	85.71%	3 Missing ⚠️

📢 Thoughts on this report? Let us know!