Pool metrics: the timeout counter never counts pool checkout timeouts, and the checkout histogram measures held time, not wait

[AlexeyShalaev]

Measured on 0.3.0 with PostgresMetrics() attached to an AsyncSessionManager with PoolSettings(size=2, max_overflow=2, timeout=1.0), eight workers running SELECT pg_sleep(:s) in a loop, sampled every half second from the Prometheus registry next to the application's own count of sqlalchemy.exc.TimeoutError raised by the pool:

   3.0 s  in_use=4/4  checkouts/s=  72  checkout wait=   55 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= 1007 ms  timeouts_total=0 errors_total=0  requests failed on pool timeout=3
   7.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1006 ms  timeouts_total=0 errors_total=0  requests failed on pool timeout=6
   8.0 s  in_use=4/4  checkouts/s=   8  checkout wait= 1007 ms  timeouts_total=0 errors_total=0  requests failed on pool timeout=7

Two things in that table.

postgres_db_connection_timeouts_total is documented as "Number of connection checkout timeouts" and it stayed at zero through seven of them. attach_metrics counts timeouts from the engine's handle_error event, which fires for DBAPI errors during execution; a QueuePool checkout timeout is raised by pool.connect() before any DBAPI call and never reaches that listener. So the one timeout a pool actually produces under load is the one the counter does not count.

postgres_db_connection_checkout_duration_seconds is the time between the checkout and checkin events, which is how long a connection was held, and the column above confirms it: 55 ms while queries took 50 ms, a second while they took a second. That is a useful number (it is the query duration seen from the pool), but its name says checkout, the guide's monitoring advice reads it as the time a caller waited for a connection, and the wait is the metric that predicts a pool outage. The wait is not exposed at all.

What I think it needs: a real checkout-wait histogram (time spent inside pool.connect() before a connection is handed out) and a timeout counter that increments when that wait ends in TimeoutError. SQLAlchemy has no pool event for "checkout requested", so the instrumentation has to sit around the acquisition: the kit already owns the pool class through resolve_pool_class / register_pool_class, and an instrumented AsyncAdaptedQueuePool subclass that times _do_get and counts its TimeoutError would cover both without touching callers; timing session.connection() in get_session would be the alternative. The existing histogram should keep its data and get a name that says what it measures (held duration), with a deprecation note in the agents page's metrics paragraph, the monitoring section of the configuration guide, and the PgBouncer guide, which quotes it.

Lab: pool_metrics_lab.py in https://github.com/bedrock-python/bedrock-python.github.io/tree/docs/production-python-series/docs/blog/lab/2026-09-07-sqlalchemy-pool-metrics.

[AlexeyShalaev]

I read attach_metrics, the pool internals and the protocols before deciding. Pool subclass it is, but timing connect() rather than _do_get. QueuePool._do_get calls itself when the non-blocking get comes back empty and the overflow race is lost, which is precisely the contended case this metric exists for; an override around it would observe the same wait twice and count one timeout as two. Pool.connect() runs once per checkout, is what Engine.raw_connection() calls for sync and async engines alike, and the pool TimeoutError passes through it exactly once. For AsyncAdaptedQueuePool the queue wait is an await_only inside that same call, so a perf_counter pair around super().connect() in the greenlet measures the time the caller actually spent suspended on the loop. It also includes the pre-ping round trip and a fresh connection's handshake when the pool grows, which I think is right: the caller waited for that too.

Wiring: AsyncSessionManager wraps whatever resolve_pool_class returned in a subclass from instrument_pool_class(pool_class, metrics) (in session.manager, next to attach_metrics) before building the engine, so registered custom pools and the six built-ins get it without touching callers; the metrics object lives on the class, which is what makes recreate() after dispose() keep it. attach_metrics stays listeners only and logs a warning when the engine's pool was not built instrumented, so a self-built engine does not end up with an empty histogram nobody notices. Timing session.connection() in the manager was the other option; it misses everything that goes through session_maker (the unit of work, both DI containers) and engine.connect(), so no.

Protocol: a new narrow CheckoutWaitRecorder with record_checkout_wait(duration, timed_out=False), runtime-checkable and picked up when the object has it. PostgresMetricsProtocol keeps its three methods, so a hand-written implementation from the guide stays valid and simply gets no wait series. record_checkout keeps its name and gets a docstring that says what it always measured.

Metrics: postgres_db_connection_checkout_wait_seconds (histogram, buckets up to 30 s so the default pool_timeout does not land in +Inf), observed for every checkout that ends with a connection or with a pool timeout; postgres_db_connection_timeouts_total fed from that timeout; the held histogram becomes postgres_db_connection_held_duration_seconds and is still emitted under postgres_db_connection_checkout_duration_seconds for this release, with a deprecation note, then goes. The handle_error path is unchanged.

Tests: unit tests on the subclass with a real QueuePool (pool_size=1, timeout=0.01: one wait, one timeout, recreate keeps recording, a raising recorder does not break the checkout), and an integration test on the container: a pool of 1 with pool_timeout=0.2, a second caller whose wait is roughly the first one's hold, a third that times out and moves the counter to exactly 1. I will run your lab against the branch and put the table in the PR.

Outside this repo: the PgBouncer post on the site is what quotes the old name, and it already describes it as held time, so it only needs the new name once this ships.

[AlexeyShalaev]

Shipped in #27, built as planned — Pool.connect() in a subclass, not _do_get, and the
manager wraps whatever resolve_pool_class returned so callers do not have to ask.

What you get:

Series
postgres_db_connection_checkout_wait_seconds	new. Time 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 to 30 s, so the default pool_timeout does not land in +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, same values, so nothing on your dashboards breaks today. It goes in a future release
postgres_db_connection_timeouts_total	now also counts pool checkout timeouts. It can only be higher than before, so an alert on it will start firing where it used to stay silent

Your lab, run unmodified against the branch — timeouts_total tracks your own count of
sqlalchemy.exc.TimeoutError exactly, where it stayed at 0:

   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

The script's checkout wait column still shows held time because it reads the deprecated
series by name — which is the confusion, in one column. Point it at
…_checkout_wait_seconds and add one for …_held_duration_seconds and the same run reads:

   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, 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 everyone waits about one query's worth — which is why the old single number
looked plausible right up until it mattered.

On your side, when this releases: nothing has to change, but

• alert on checkout_wait_seconds rather than the old histogram — it is the one that climbs
  before anything fails, and timeouts_total is what it turns into at pool_timeout;
• move panels off checkout_duration_seconds to held_duration_seconds for the same
  numbers, before it is removed;
• if you attach PostgresMetrics to an engine you built yourself rather than through
  AsyncSessionManager, wrap the pool class with
  instrument_pool_class(pool_class, metrics) — the wait cannot be observed from a
  listener. attach_metrics logs a warning if you did not, so it will not be silent.

PostgresMetricsProtocol is unchanged. The new capability is a separate
CheckoutWaitRecorder, so a hand-written metrics implementation stays valid and just
publishes no wait series until it grows a record_checkout_wait.

The PgBouncer post on the site quotes the old name and already describes it as held time, so
it only needs the name swapped once this is released — not part of this change.