Skip to content

fix(db): add missing index on request_logs.created_at - #811

Open
sjawhar wants to merge 1 commit into
LuthienResearch:mainfrom
trajectory-labs-pbc:fix/request-logs-created-at-index
Open

sjawhar wants to merge 1 commit into
LuthienResearch:mainfrom
trajectory-labs-pbc:fix/request-logs-created-at-index

Conversation

@sjawhar

@sjawhar sjawhar commented Aug 23, 2026 •

Copy link
Copy Markdown
Collaborator

Summary

request_logs has no index on created_at (10 other indexes exist on this table, none on created_at). Any time-windowed query against it forces a full-table Parallel Seq Scan — most notably a downstream deployment's capture-liveness monitor Lambda, which runs a "rows in the last 15 minutes" check every 5 minutes forever via an EventBridge schedule. At 4.08M rows / 3.7GB, that scan reads ~475k buffer pages and takes ~380ms on every single invocation, regardless of traffic — a fixed, ever-growing tax on the production Aurora cluster's CPU.

This PR is one of two required parts (see Companion PR below) — the index alone or the companion query rewrite alone is not sufficient; both are needed together (confirmed empirically: EXISTS() without this index can be as slow as, or slower than, the original count(*), since the planner has no way to find a matching row early without an index).

What changed

  • migrations/postgres/022_add_request_logs_created_at_index.sql: CREATE INDEX CONCURRENTLY IF NOT EXISTS idx_request_logs_created_at ON request_logs (created_at); — CONCURRENTLY because request_logs is a live, multi-million-row production table; a plain CREATE INDEX would hold a lock blocking every in-flight INSERT for the full build duration.
  • migrations/sqlite/022_add_request_logs_created_at_index.sql + the matching bundled copy in src/luthien_proxy/utils/sqlite_migrations/ (per migrations/AGENTS.md) — plain CREATE INDEX IF NOT EXISTS (no CONCURRENTLY; SQLite doesn't have/need it).
  • Changelog fragment.

Production rollout note (read before deploying)

This migration runs automatically at gateway container startup (docker/start-gateway.sh -> docker/run-migrations.sh) on the next deploy. Two things reviewers/operators should know before that happens:

  1. docker/run-migrations.sh invokes psql -f without -v ON_ERROR_STOP=1. By default, psql scripts can exit 0 even after a SQL error mid-script, and the runner unconditionally records the migration as applied in _migrations right after. For most migrations this is low-risk; for this one specifically, an interrupted/failed CREATE INDEX CONCURRENTLY can leave an invalid index behind under the same name, which IF NOT EXISTS would then treat as "already there" on any retry — silently leaving production without a usable index while the tracker says it's applied. This is a pre-existing gap in the migration runner (not introduced by this PR, and out of scope for it), but it's a real risk specifically for this migration. Recommend fixing run-migrations.sh to pass -v ON_ERROR_STOP=1 before/alongside this landing, and verifying pg_index.indisvalid for idx_request_logs_created_at after deploy regardless.
  2. Consider decoupling this from normal gateway-startup migration timing. A downstream deployment's ECS service config explicitly notes health_check_grace_period_seconds=120 "covers normal boot; heavy one-time migrations should still be decoupled from app startup." CREATE INDEX CONCURRENTLY on a live 3.7GB table is exactly that kind of heavy one-time migration — if it runs long, new ECS tasks could sit unbound behind the ALB, exceed the grace period, get killed mid-build, and loop the deployment. Recommend running this migration once as a standalone step (e.g. the existing migrations Docker image / Dockerfile.migrations, built for exactly this) against production ahead of the next gateway deploy, then verifying EXPLAIN shows an index scan before rolling the gateway service.

I do not have write access to production Aurora to apply or verify this migration myself (only luthien_admin_iam, a read-only SELECT/EXPLAIN role — confirmed via a live CREATE INDEX attempt returning ERROR: must be owner of table request_logs), so I could not execute either recommendation above myself.

Verification

  • uv run pytest tests/luthien_proxy/unit_tests/utils/test_migration_naming.py -m "not integration" -> 54 passed.
  • uv run pytest tests/luthien_proxy/integration_tests/test_migration_sync.py -m integration against a fresh local postgres:16-alpine -> 1 passed (Postgres and SQLite migration sets produce equivalent schemas, including this migration).
  • Applied the full migration set (docker/run-migrations.sh) against a fresh local Postgres and confirmed it applies cleanly and is correctly tracked/skipped on re-run.
  • Seeded a local Postgres with 2.6M synthetic request_logs rows spread over 30 days and ran EXPLAIN ANALYZE before/after:
    • Before (no index): count(*) query -> Parallel Seq Scan, 99.3ms, "Rows Removed by Filter: 863718".
    • After (index + ANALYZE): both the old count(*) query and the new EXISTS(...) query (see companion PR) -> Index Only Scan, <1ms.
  • Live production Aurora (read-only, via luthien_admin_iam) confirmed via EXPLAIN (ANALYZE, BUFFERS) that the current count(*) monitor query is still a Parallel Seq Scan today (382.670ms, 475128 buffer hits, "Rows Removed by Filter: 1394125") and that no created_at index exists yet on the live table.

Companion PR

A companion change in a downstream deployment rewrites the capture-monitor Lambda's query from count(*) to EXISTS(...).

@sjawhar
sjawhar marked this pull request as ready for review August 23, 2026 16:42
request_logs has no index on created_at, so any time-windowed query against
it forces a full-table Parallel Seq Scan. In production this is a fixed,
traffic-independent cost that grows with the table: the capture-liveness
monitor (agent-c's luthien_capture_monitor Lambda) runs a 15-minute-window
query every 5 minutes forever, and at 4M+ rows / 3.7GB that scan took
~380ms of CPU on every single invocation regardless of load.

Adds idx_request_logs_created_at via CREATE INDEX CONCURRENTLY (the table is
live and multi-million-row) with a matching SQLite migration and the copy
into utils/sqlite_migrations/ per migrations/AGENTS.md.

Verified locally: seeded 2.6M synthetic rows, confirmed EXPLAIN ANALYZE goes
from Parallel Seq Scan (99ms) to Index Only Scan (<1ms) once the index and
ANALYZE are present.
@legion-implementer
legion-implementer Bot force-pushed the fix/request-logs-created-at-index branch from 6d9ed85 to 9e8c040 Compare August 23, 2026 16:43
legion-implementer Bot pushed a commit to trajectory-labs-pbc/luthien-proxy that referenced this pull request Aug 23, 2026
psql -f ran without -v ON_ERROR_STOP=1, so a migration with a failing
statement would print the error, keep running later statements in the
same file, and still exit 0 -- letting the migration get recorded as
applied. Every psql call now goes through an ON_ERROR_STOP=1 wrapper,
and the one pipe that could mask a psql exit code (the "already
applied?" check, via | tr -d ' ') is gone in favor of -t -A.

Also closes the CREATE INDEX CONCURRENTLY IF NOT EXISTS retry trap:
that clause matches by name only, so an index left INVALID by an
interrupted concurrent build is silently accepted as already-there on
a retried deploy, with no error for ON_ERROR_STOP to catch. After a
migration applies, the runner now checks pg_index.indisvalid for any
index it builds CONCURRENTLY before recording success -- protecting
idx_request_logs_created_at (LuthienResearch#811) from shipping invalid.

Adds a 12-test integration suite pinning both behaviors against a real
Postgres, and wires it into CI (scoped to this file -- the broader
integration marker has pre-existing unrelated failures that have never
run in CI, a separate concern flagged but not fixed here).

PR LuthienResearch#812
legion-implementer Bot pushed a commit to trajectory-labs-pbc/luthien-proxy that referenced this pull request Sep 8, 2026
…ompleted_at T-form mismatch

Round-2 reviewer findings on LuthienResearch#806:

(1) Migration number collision: 022 is already claimed by sibling PR LuthienResearch#811
(migrations/{postgres,sqlite}/022_add_request_logs_created_at_index.sql) and
023 by LuthienResearch#813. Renumbered this migration's three copies (postgres, sqlite,
bundled) to 024, the next free prefix.

(2) request_logs.started_at/completed_at are written via to_timestamp(?) (a
float unix-epoch bind, translated by _translate_params to SQLite's native
datetime(?, 'unixepoch')), never a raw datetime bind -- so the previous
commit's _convert_arg fix never touched them, and SQLite's own
datetime(unixepoch) always emits a space separator, permanently (a
migration alone cannot fix this for future rows). request_log/service.py's
after/before filters bind a raw datetime (datetime.fromisoformat), which
after the previous commit becomes T-form via the now-fixed _convert_arg.
Without this fix, a same-day after/before filter would silently return
wrong results forever -- not just for legacy rows, for every row written
after the previous commit landed. Fixed by wrapping the to_timestamp(?)
translation in replace(..., ' ', 'T'). Migration 024 also now backfills
existing request_logs.started_at/completed_at (added the two UPDATE
statements; same LIKE-gated, idempotent shape as the other four columns).

red (test_to_timestamp_write_comparable_with_datetime_bind_filter against
the to_timestamp(?) → datetime(?, 'unixepoch') translation, no replace()):
  AssertionError: assert '2026-08-10 12:00:00' == '2026-08-10T12:00:00'
also red: test_to_timestamp (asserted bare 'datetime(?, ...)' output before)

green (same tests, replace(..., ' ', 'T') wrap restored):
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_db_sqlite.py -k 'test_to_timestamp or test_to_timestamp_write_comparable' -q --no-cov
  -> 2 passed

green (full file + repo-wide gate on the changed files):
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_db_sqlite.py -> 46 passed
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_migration_naming.py tests/luthien_proxy/unit_tests/utils/test_sqlite_migrations_are_native.py -> all pass
  uv run pytest tests/luthien_proxy/unit_tests -> exit 0
  ruff format --check / ruff check / pyright on changed files -> clean

Omp-Session: 01a081d4-2514-7000-b8e2-ff8548776146

This branch has not been deployed

No deployments
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