fix(backend): stop task-manager event queries from flipping to a quadratic generic plan - #10379
fix(backend): stop task-manager event queries from flipping to a quadratic generic plan#10379fatih-acar wants to merge 2 commits into
Conversation
…ratic generic plan The activity log intermittently stalled for 30s+ in e2e CI (and for real users) while every other request stayed fast. Reproduced on a CI-parity testcontainers stack: the task manager's asyncpg connections use named prepared statements, and after five executions Postgres switches the /infrahub/events/filter count/read statements to a generic plan chosen without seeing the parameter values. For these filters (a wide occurred window plus a JSON label match on event_resources) that generic plan is a quadratic nested-loop semi join - measured through the live endpoint: executions 1-5 complete in ~20ms, execution 6 onward takes 8.9s at just 5k events / 40k resources, growing quadratically with event volume. The flip is per pool connection, which is what made it look like a rare flake: one connection runs the pathological plan while its siblings answer in milliseconds, and a page reload lands on a healthy one. Three layers then turned a slow query into a silent black hole: the query_events retry loop swallowed up to four 500s back to back, the Prefect client retries read timeouts five times at DEBUG, and the e2e haproxy config disables all timeouts. - Run SET LOCAL plan_cache_mode = force_custom_plan at the start of the events/filter transaction, so these two queries are always planned with the real filter values. The countermeasure is scoped to this transaction only - the rest of the Prefect server keeps its prepared-statement plan caching - and costs ~0.25ms planning per statement. Validated on the repro stack via pg_stat_statements (track_planning): unpatched plans=18/calls=30 with the 8.9s flip at execution 6; patched plans=30/calls=30 with every call at 18-20ms. - Only run the unbounded count when the GraphQL query selects `count` (new include_total field on the events/filter input, default true so older clients keep the previous behavior). The activity-log UI never selects it, so its page loads skip the aggregate entirely. - Log a warning on each query_events retry so a stalling task manager is visible in the server logs instead of silent. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
There was a problem hiding this comment.
4 issues found across 6 files
Confidence score: 3/5
backend/infrahub/task_manager/event/query.pycan returncount: 0for aliased selections such astotalCount: count, producing an incorrect total without an obvious error — handle aliases when detecting the count field.- The new omitted-
countpath inbackend/infrahub/infrahub/prefect_server/database.pyand selection-dependentinclude_totalbehavior inbackend/infrahub/task_manager/event/query.pylack regression coverage, so changes could silently alter event-query totals — add focused tests for both cases. backend/infrahub/task_manager/event/query.pylogs the fourth failed POST as a retry even though no attempts remain, which can mislead operators during failures — emit a terminal-failure message forattempt == 4.
Prompt for AI agents (unresolved issues)
Check if these issues are valid — if so, understand the root cause of each and fix them. If appropriate, use sub-agents to investigate and fix each issue separately.
<file name="backend/infrahub/prefect_server/database.py">
<violation number="1" location="backend/infrahub/prefect_server/database.py:21">
P2: Custom agent: **Flag AI Slop and Fabricated Changes**
When the caller omits `count`, this new branch skips the expensive aggregate and returns `0`, but no regression test exercises that behavior. Add an event-query test without `count` that verifies the response count and prevents the count query from running.</violation>
</file>
<file name="backend/infrahub/task_manager/event/query.py">
<violation number="1" location="backend/infrahub/task_manager/event/query.py:419">
P3: On the fourth failed POST, this warning says the query is retrying even though the loop has exhausted all attempts and raises after the sleep. Emit a terminal-failure message for `attempt == 4` so logs distinguish retries from exhausted requests.</violation>
<violation number="2" location="backend/infrahub/task_manager/event/query.py:456">
P2: Custom agent: **Flag AI Slop and Fabricated Changes**
The new selection-dependent `include_total` behavior has no regression coverage: existing event-query tests always request `count`, so they never verify that edge-only queries send `include_total=False` while count queries send `True`. Add focused assertions around the request payload or mocked `query_events` call for both selections.</violation>
<violation number="3" location="backend/infrahub/task_manager/event/query.py:456">
P3: `include_total = "count" in fields` misses an aliased selection (e.g. `totalCount: count`), because the field extractor keys the selection by field name, not alias. Such a query would silently receive `count: 0` even though it requested the aggregate. Match on the underlying field definitions instead of the raw selection key.</violation>
</file>
Shadow auto-approve: would not auto-approve because issues were found.
Re-trigger cubic
| include_total: bool = True, | ||
| ) -> tuple[list[ReceivedEvent], int]: | ||
| count = await raw_count_events(session, filter) # type: ignore[attr-defined] | ||
| count = await raw_count_events(session, filter) if include_total else 0 # type: ignore[attr-defined] |
There was a problem hiding this comment.
P2: Custom agent: Flag AI Slop and Fabricated Changes
When the caller omits count, this new branch skips the expensive aggregate and returns 0, but no regression test exercises that behavior. Add an event-query test without count that verifies the response count and prevents the count query from running.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At backend/infrahub/prefect_server/database.py, line 21:
<comment>When the caller omits `count`, this new branch skips the expensive aggregate and returns `0`, but no regression test exercises that behavior. Add an event-query test without `count` that verifies the response count and prevents the count query from running.</comment>
<file context>
@@ -12,9 +12,13 @@
+ include_total: bool = True,
) -> tuple[list[ReceivedEvent], int]:
- count = await raw_count_events(session, filter) # type: ignore[attr-defined]
+ count = await raw_count_events(session, filter) if include_total else 0 # type: ignore[attr-defined]
page = await read_events(session, filter, limit=page_size, offset=offset) # type: ignore[attr-defined]
events = [ReceivedEvent.model_validate(e, from_attributes=True) for e in page]
</file context>
|
|
||
| # The count is an unbounded aggregate over the whole filter window and is by far | ||
| # the most expensive part of the endpoint, so only ask for it when selected. | ||
| include_total = "count" in fields |
There was a problem hiding this comment.
P2: Custom agent: Flag AI Slop and Fabricated Changes
The new selection-dependent include_total behavior has no regression coverage: existing event-query tests always request count, so they never verify that edge-only queries send include_total=False while count queries send True. Add focused assertions around the request payload or mocked query_events call for both selections.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At backend/infrahub/task_manager/event/query.py, line 456:
<comment>The new selection-dependent `include_total` behavior has no regression coverage: existing event-query tests always request `count`, so they never verify that edge-only queries send `include_total=False` while count queries send `True`. Add focused assertions around the request payload or mocked `query_events` call for both selections.</comment>
<file context>
@@ -438,8 +451,14 @@ async def query(
+ # The count is an unbounded aggregate over the whole filter window and is by far
+ # the most expensive part of the endpoint, so only ask for it when selected.
+ include_total = "count" in fields
+
async with get_client(sync_client=False) as client:
</file context>
| # Each failed attempt can hide up to a full task-manager request timeout, | ||
| # so a silent loop here turns into a multi-minute stall for the caller. | ||
| log.warning( | ||
| "Event query to the task manager failed, retrying", |
There was a problem hiding this comment.
P3: On the fourth failed POST, this warning says the query is retrying even though the loop has exhausted all attempts and raises after the sleep. Emit a terminal-failure message for attempt == 4 so logs distinguish retries from exhausted requests.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At backend/infrahub/task_manager/event/query.py, line 419:
<comment>On the fourth failed POST, this warning says the query is retrying even though the loop has exhausted all attempts and raises after the sleep. Emit a terminal-failure message for `attempt == 4` so logs distinguish retries from exhausted requests.</comment>
<file context>
@@ -396,17 +396,30 @@ async def query_events(
+ # Each failed attempt can hide up to a full task-manager request timeout,
+ # so a silent loop here turns into a multi-minute stall for the caller.
+ log.warning(
+ "Event query to the task manager failed, retrying",
+ attempt=attempt,
+ status_code=exc.response.status_code,
</file context>
| "Event query to the task manager failed, retrying", | |
| "Event query to the task manager failed, retrying" | |
| if attempt < 4 | |
| else "Event query to the task manager failed", |
|
|
||
| # The count is an unbounded aggregate over the whole filter window and is by far | ||
| # the most expensive part of the endpoint, so only ask for it when selected. | ||
| include_total = "count" in fields |
There was a problem hiding this comment.
P3: include_total = "count" in fields misses an aliased selection (e.g. totalCount: count), because the field extractor keys the selection by field name, not alias. Such a query would silently receive count: 0 even though it requested the aggregate. Match on the underlying field definitions instead of the raw selection key.
Prompt for AI agents
Check if this issue is valid — if so, understand the root cause and fix it. At backend/infrahub/task_manager/event/query.py, line 456:
<comment>`include_total = "count" in fields` misses an aliased selection (e.g. `totalCount: count`), because the field extractor keys the selection by field name, not alias. Such a query would silently receive `count: 0` even though it requested the aggregate. Match on the underlying field definitions instead of the raw selection key.</comment>
<file context>
@@ -438,8 +451,14 @@ async def query(
+ # The count is an unbounded aggregate over the whole filter window and is by far
+ # the most expensive part of the endpoint, so only ask for it when selected.
+ include_total = "count" in fields
+
async with get_client(sync_client=False) as client:
</file context>
…ment The release-notes Vale style rejects the short form. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
There was a problem hiding this comment.
0 issues found across 1 file (changes from recent commits).
Confidence score: 5/5
- Automated review surfaced no issues in the provided summaries.
- No files require special attention.
Shadow auto-approve: would not auto-approve. Auto-approval blocked by 4 unresolved issues from previous reviews.
Re-trigger cubic
Why
The activity log intermittently stalls for 30s+ — the page sits on "Loading..." while every other request on the instance answers in milliseconds. In e2e CI this surfaced as the
test_filter_by_accountflake (runs 31707450288, 32490367256): theGET_INFRAHUB_EVENTSrequest black-holes, the filter bar never renders, and the test dies on a 30s click timeout while sibling GraphQL queries fired the same millisecond complete in ~30ms.Root cause, reproduced on a CI-parity testcontainers stack: the task manager's asyncpg connections execute the
/infrahub/events/filtercount/read statements as named prepared statements, and after five executions Postgres switches them to a generic plan chosen without seeing the parameter values. For these filters (wideoccurredwindow + JSON label match onevent_resources) the generic plan is a quadratic nested-loop semi join. Measured through the live endpoint: executions 1–5 take ~20ms, execution 6 onward takes 8.9s at just 5k events / 40k resources, growing quadratically with event volume. The flip is per pool connection — one connection runs the pathological plan while its siblings stay fast — which is why it presented as a rare flake, and why a page reload "fixed" it.Three layers then turned one slow query into a silent, unbounded hang: the
query_eventsretry loop swallowed up to four 500s back to back, the Prefect client silently retries read timeouts five times (logged at DEBUG), and the e2e haproxy config disables all timeouts.Non-goals: no change to Prefect-server-wide prepared-statement caching (a global
statement_cache_size=0was considered and rejected as an unbounded performance surface), no changes to Prefect's own query builders.What changed
SET LOCAL plan_cache_mode = force_custom_planat the start of its transaction (Postgres only), so its two queries are always planned with the real filter values. Scoped to this transaction — every other Prefect statement keeps prepared-statement plan caching. Cost: ~0.25ms planning per statement.count(*)— by far the endpoint's most expensive statement — now only runs when the GraphQL query selectscount(newinclude_totalinput field, defaulttrue, so older clients keep the previous behavior). The activity-log UI never selects it, so its page loads skip the aggregate entirely.query_eventsretry now logs a warning, so a stalling task manager is visible in the server logs instead of silent.dev/knowledge/backend/events.mdgains a "Query-path performance constraints" section recording both invariants.No GraphQL schema changes; the events/filter wire change is backward-compatible in both directions (pydantic defaults/extra-ignore).
How to review
backend/infrahub/prefect_server/events.py— theSET LOCALand its scoping rationale.backend/infrahub/task_manager/event/query.py—include_totalderivation from the GraphQL selection, retry warning.backend/infrahub/prefect_server/{models,database}.py— theinclude_totalplumbing.How to test
Validated on a CI-parity repro stack (testcontainers compose + 5k synthetic events / 40k event_resources) with
pg_stat_statements.track_planning=on, 30 sequential requests to/infrahub/events/filter:Impact & rollout
include_totaldefaults totrue; old client ↔ new server and new client ↔ old server both keep prior behavior.Checklist
dev/knowledge/backend/events.md)🤖 Generated with Claude Code