Skip to content

The empty-read diagnostic's latest-collector-outcome lookup sorts every retained collection_log row for the (server, collector) by log_id: 0.44 s warm, 9.1 s max, and it doubles as retention grows to 60 days #4974

Closed

Description

@erikdarlingdata

Class: bug (performance). DarlingRuntimePrecondition.LatestCollectorOutcomeSql answers "how did this collector's latest run end?" whenever an MCP tool's read comes back empty. It does ORDER BY log_id DESC LIMIT 1 over collection_log for one (server, collector), with no time bound. collection_log has no primary key and no index on log_id, so every call reads and sorts every retained row for that pair, across every chunk, most of them compressed.

The sibling in the same class, CollectorLastRunSql, was already changed to ORDER BY collection_time DESC for exactly this reason. Its doc comment: "Ordering by log_id instead would read the server's whole retained history on every call". #3496 fixed the same pattern in the alerting read.

Measured (a 43-server SQL Server store, v3.9.0)

  • pg_stat_statements (mcp role): 252 calls, mean 1.6 s, max 9.1 s.
  • The callers: the tools whose reads are often empty, which makes this a hot path:
    • get_deadlocks (most of the calls);
    • the blocked-process-report tool, get_query_store_top, get_running_jobs and get_long_query_completions;
    • about ten get_pg_* tools.
  • EXPLAIN (ANALYZE, BUFFERS), one server, collector deadlocks, warm:
    • 439 ms;
    • Limit → Gather Merge → Sort (Sort Key: collection_log.log_id DESC, top-N heapsort) → Parallel Append over every retained chunk (34, most compressed);
    • 8,120 rows actually read and sorted to return 1 (the planner estimated 598 k);
    • shared hit 10,331 / read 1,810.
  • This collector's rows are sparse; a busy collector's pair holds far more rows per day. The read scales with retention. The store's collection_log now keeps 60 days (it was capped at 30 by a hand-added retention job until 10-02), so the scan length roughly doubles over the next month (inferred from the plan's shape).

Where

Darling/PerformanceMonitor.Darling.Service/Mcp/DarlingRuntimePrecondition.cs:

SELECT status, error_message, collection_time
FROM collection_log
WHERE server_id = $1
AND   collector_name = $2
ORDER BY log_id DESC
LIMIT 1

Its doc comment gives the reason for log_id: two runs in one cycle can share a timestamp, and "the latest run" is the claim.

Fix direction (inferred)

  • Answer from the newest chunk first: ORDER BY collection_time DESC, log_id DESC, which idx_collection_log_watermark (server_id, collector_name, collection_time DESC) already serves. Or a time-bounded candidate set re-ordered by log_id, so the "latest run" claim keeps its tie-break.
  • Probably no new index or migration rung is needed. To be confirmed by EXPLAIN before and after.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions