Skip to content

feat(observability): diagnose blocked-loop vs pool-exhaustion on stalled /health - #2942

Merged
nicoloboschi merged 1 commit into
mainfrom
feat/loop-pool-observability
Jul 24, 2026
Merged

feat(observability): diagnose blocked-loop vs pool-exhaustion on stalled /health#2942
nicoloboschi merged 1 commit into
mainfrom
feat/loop-pool-observability

Conversation

@nicoloboschi

Copy link
Copy Markdown
Collaborator

Problem

The API and worker run the /health handler and all task work on a single asyncio event loop, and /health acquires a database connection. So a failing Kubernetes liveness probe has two very different root causes that are currently indistinguishable:

  1. The event loop is blocked by synchronous work on the loop (CPU-bound parsing, a mis-offloaded SDK call, a third-party lib doing inline work). /health can't be scheduled → probe fails. A restart helps.
  2. The connection pool is exhausted/health's own SELECT 1 can't acquire a connection and blocks up to the acquire timeout, with the loop completely idle. A restart just thrashes and can make it worse.

Today both look identical from the outside: pod restarted, cause unknown. This PR makes the failure self-diagnosing instead of working around it.

What this adds

Two always-on, cheap signals:

1. Event-loop stall watchdog (hindsight_api/loop_watchdog.py)

Runs in a separate OS thread — deliberately, because a coroutine-based monitor would be frozen by the very stall it's trying to observe. It pings the loop and, when the loop fails to service the ping within a threshold, logs the loop thread's stack (naming the exact blocking frame) and emits hindsight.event_loop.stalls / hindsight.event_loop.stall_duration. Works with uvloop (unlike monkeypatch-based blocking detectors). Never raises, never touches loop work. Wired into the worker CLI and the API lifespan.

2. DB pool acquire instrumentation (engine/db/pool_instrumentation.py)

asyncpg exposes pool size/idle but not how many callers are queued waiting for a connection — the signal that actually distinguishes exhaustion from a busy-but-healthy pool. This tracks that (hindsight.db.pool.waiting gauge), records an acquire-wait histogram, and logs a warning with pool stats when an acquire waits too long. Wired into both the PostgreSQL and Oracle backends. health_check() now reports db_acquire_ms and pool utilization in its response payload, so a slow/failing /health is diagnosable from the response alone.

At the failing moment you now get one of:

  • EVENT LOOP BLOCKED for 2.1s ... <stack naming the frame> → liveness problem, restart helps.
  • slow DB pool acquire: waited 30.0s ... (in_use=10 max=10 idle=0 waiting=7) → readiness problem, restart thrashes it.

Config (static, server-level; enabled by default)

Env var Default
HINDSIGHT_API_LOOP_WATCHDOG_ENABLED true
HINDSIGHT_API_LOOP_WATCHDOG_STALL_THRESHOLD_MS 1000
HINDSIGHT_API_LOOP_WATCHDOG_POLL_INTERVAL_MS 250
HINDSIGHT_API_DB_ACQUIRE_WARN_THRESHOLD_MS 1000

Testing

  • tests/test_loop_watchdog.py — detects on-loop blocks (and captures the culprit stack), ignores off-loop (threaded) work, stays quiet on a responsive loop.
  • tests/test_pool_instrumentation.py — waiter counting through success / mid-acquire / acquire-failure, and slow-acquire logging with pool stats.
  • Validated end-to-end against a real pg pool: under a saturated max_size=1 pool, a second acquirer registered waiting=1 and logged the slow-acquire warning with real stats.

Context

Came out of a report (@carter, vectorize-io) of /health hanging in a Bedrock-heavy worker. Investigation showed litellm already offloads boto3 credential resolution to a thread (so that specific cause didn't reproduce), which is exactly why runtime visibility — not a workaround — is the right fix: whatever blocks the loop or exhausts the pool next will now name itself in the logs.

…led /health

The API and worker run /health and all task work on a single event loop, and
/health acquires a DB connection. A failing liveness probe therefore has two
very different causes that today are indistinguishable: the event loop is
blocked by synchronous work (a restart helps), or the connection pool is
exhausted and /health can't get a connection while the loop is idle (a restart
just thrashes). Add two always-on, cheap signals so the failure is
self-diagnosing instead of an opaque restart.

LoopWatchdog (hindsight_api/loop_watchdog.py): runs in a separate OS thread —
deliberately, since a coroutine-based monitor would be frozen by the very stall
it's watching — pings the loop, and on a stall past a threshold logs the loop
thread's stack (naming the blocking frame) and emits
hindsight.event_loop.stalls / stall_duration. Works with uvloop. Wired into the
worker CLI and the API lifespan; enabled by default.

DB pool acquire instrumentation (engine/db/pool_instrumentation.py): tracks
callers currently queued for a connection (hindsight.db.pool.waiting gauge, the
signal that actually distinguishes exhaustion from a busy-but-healthy pool),
records an acquire-wait histogram, and logs a warning with pool stats when an
acquire waits too long. Wired into both the PostgreSQL and Oracle backends.
health_check() now reports db_acquire_ms and pool utilization in its payload.

Static config: HINDSIGHT_API_LOOP_WATCHDOG_ENABLED / _STALL_THRESHOLD_MS /
_POLL_INTERVAL_MS, HINDSIGHT_API_DB_ACQUIRE_WARN_THRESHOLD_MS.

Tests: test_loop_watchdog.py (detects on-loop blocks, ignores off-loop work,
quiet when responsive) and test_pool_instrumentation.py (waiter counting through
success/mid-acquire/failure, slow-acquire logging).
@nicoloboschi
nicoloboschi merged commit 489d55f into main Jul 24, 2026
198 of 204 checks passed
@nicoloboschi
nicoloboschi deleted the feat/loop-pool-observability branch July 24, 2026 10:11
nicoloboschi added a commit that referenced this pull request Jul 24, 2026
The three Oracle jobs run the Oracle 23ai `free` service image, which
together with the Python ML deps (torch) exhausts the runner's ~14 GB root
disk. Two symptoms, one cause:

- uv fails to extract a wheel with "No space left on device (os error 28)"
  (fast ~2 min failure), and
- a near-full disk starves I/O badly enough to trip the 30-minute job
  timeout.

test-python-client-oracle and test-typescript-client-oracle have been red on
every open PR (#2941, #2942, #2943) from this, independent of the code under
test. Reclaim ~20 GB of preinstalled tooling (the same jlumbroso action the
Docker build job already uses) before the Oracle setup step.

docker-images stays false here: unlike the Docker build job, the Oracle
service container is already running by the time steps execute, so pruning
images could disrupt it. The savings come from the tool cache, Android SDK,
.NET, Haskell, large apt packages and swap.
nicoloboschi added a commit that referenced this pull request Jul 24, 2026
…ain deadlock (#2948)

* ci(oracle): free runner disk space before Oracle jobs

The three Oracle jobs run the Oracle 23ai `free` service image, which
together with the Python ML deps (torch) exhausts the runner's ~14 GB root
disk. Two symptoms, one cause:

- uv fails to extract a wheel with "No space left on device (os error 28)"
  (fast ~2 min failure), and
- a near-full disk starves I/O badly enough to trip the 30-minute job
  timeout.

test-python-client-oracle and test-typescript-client-oracle have been red on
every open PR (#2941, #2942, #2943) from this, independent of the code under
test. Reclaim ~20 GB of preinstalled tooling (the same jlumbroso action the
Docker build job already uses) before the Oracle setup step.

docker-images stays false here: unlike the Docker build job, the Oracle
service container is already running by the time steps execute, so pruning
images could disrupt it. The savings come from the tool cache, Android SDK,
.NET, Haskell, large apt packages and swap.

* ci(oracle): trim disk reclaim to the fast, high-yield options

The first pass enabled every reclaim, which cost ~4 minutes of job time —
counterproductive on jobs that are already fighting a 30-minute limit.

android + dotnet + haskell + swap are a few rm -rf's worth ~16-21 GB, which
is ample headroom for the Oracle image plus torch. Dropped:
- large-packages: apt-get remove, costs minutes for little extra space;
- tool-cache: deletes the preinstalled Python that actions/setup-python then
  re-downloads, making the job slower rather than faster.

* fix(retain): flush entity stats after releasing the connection (Oracle hang)

Retain hung forever on the Oracle backend: every retain test burned its 120s
client timeout while the server sat idle, so test-python-client-oracle and
test-typescript-client-oracle only ever reached ~5% of the suite before the
30-minute job limit.

The server was not slow — it was deadlocked. flush_pending_stats() acquires
its own connection, but it was being called while the enclosing
acquire_with_retry(...) block still held one:

  async with acquire_with_retry(pool) as conn:   # conn checked out
      async with conn.transaction():             # SAVEPOINT only
          ...write facts/entities...
      await entity_resolver.flush_pending_stats()  # takes a 2nd connection

oracledb does not autocommit and OracleConnection.transaction() is only a
SAVEPOINT, so the write is committed by OracleBackend.acquire() when its block
exits. Connection #2's `UPDATE entities ...` therefore waits on row locks held
by the still-open connection #1, which cannot commit until the call returns —
a circular wait. Oracle never reports ORA-00060 because session #1 is blocked
in Python, not on the database, so it hangs indefinitely instead of erroring.

Move the flush after the acquire block in all three call sites (streaming
retain, delta retain, transfer importer), which is what its own docstring
already required ("must be called AFTER the retain transaction commits") and
which PostgreSQL satisfied only by accident via asyncpg autocommit.

Guarded with an AST lint test rather than a behavioural one: the deadlock
cannot be reproduced against PostgreSQL, which is what the suite runs on.

* test(repair): retry the concurrent index drop on deadlock

test_dry_run_creates_nothing still flaked in test-api shard 3. CONCURRENTLY
avoids ACCESS EXCLUSIVE but still takes ShareUpdateExclusive, which conflicts
with the ShareLock a fresh bank's plain CREATE INDEX holds — and that one
cannot be made concurrent, since it runs inside the bank-create transaction.
So _drop_bank_indexes can still be picked as the deadlock victim while another
xdist worker seeds a bank:

  Process A waits for ShareUpdateExclusiveLock on memory_units; blocked by B.
  Process B waits for ShareLock on virtual transaction; blocked by A.

The bank-create side already retries (#2943); give the drop the same treatment.
The drop is idempotent, so retrying is safe.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant