Skip to content

procedure_stats keeps only the top 150 procedures by lifetime elapsed time, and on busy primaries it misses about 16% of procedure CPU #5449

Closed
Closed
procedure_stats keeps only the top 150 procedures by lifetime elapsed time, and on busy primaries it misses about 16% of procedure CPU#5449
Labels
bugSomething isn't working

Description

@erikdarlingdata
erikdarlingdata
opened on Oct 6, 2026

Claude posting for Erik Darling.

On SQL Server primaries that run more than 150 distinct procedures, procedure_stats truncates every run at 150 rows. It ranks by lifetime total_elapsed_time since each plan was cached, so it keeps the oldest long-cached plans and drops procedures that are busy now. On one production store, Darling's procedure CPU over 7 days was about 16% lower than an independent sampler's on the same servers.

The collector

PerformanceMonitor.Collectors/ProcedureStatsCollector.cs. It's shared, so it applies to Lite and Darling both.

  • Every branch is SELECT TOP (150) … ORDER BY total_elapsed_time DESC, over sys.dm_exec_procedure_stats rows with last_execution_time >= DATEADD(MINUTE, -10, GETDATE()).
  • total_elapsed_time is cumulative since the plan was cached. So a plan cached weeks ago outranks a procedure that ran far more in the last 10 minutes but was recompiled this morning.

Measured (build 3.9.0-nightly.20261006.515)

Store A: 43 primaries Store B: 42 replicas
procedure_stats runs in one hour that returned exactly 150 rows 2,460 of 2,580 (95%), on 41 of 43 servers 283 of 2,520 (11%), on 12 servers; median 88 rows
Distinct procedures per server per day ~340–390 ~160
Procedure CPU, 7 days (Sep 28 – Oct 4), Darling vs an independent sampler of dm_exec_procedure_stats on the same servers 2,522 vs 3,003 CPU-h (Darling 16% lower) 3,288 vs 3,292 CPU-h (agree to 0.1%)
  • The independent sampler keeps the top 250 procedures per minute, ranked by in-interval elapsed time.
  • Where the cap doesn't bind (store B), the two agree almost exactly. So the gap on store A is the cap and its ranking, not the delta math.
  • Per change, on the procedures we tuned, Darling read 5–22% lower on store A. The heaviest procedure's rows in small tenant databases fall below the cap.

Options (not decided)

  1. Rank by in-window work instead of lifetime work. For example TOP (150) by total_elapsed_time minus the previous snapshot's value. The host already keeps per-key baselines in CollectorDeltaCalculator.
  2. Raise the cap, or make it configurable. Measure the run cost first: the plan apply is already bounded to the survivors (query_stats and procedure_stats render plan XML BELOW the TOP: 2,434 TVF executions for 200 kept rows - validated 6x fix from field investigation #1959).
  3. Two tiers: the top N by lifetime work for plan capture, and every executed procedure for the numbers. The numeric columns are cheap; the plans are what the cap protects.

Downstream: any per-server or fleet procedure CPU total from store A is a floor, including the Friday-CPU view's baselines.

Activity

  1. erikdarlingdata
    added
    bugSomething isn't working
    on Oct 6, 2026

  2. erikdarlingdata commented on Oct 7, 2026

    @erikdarlingdata
    erikdarlingdata
    on Oct 7, 2026
    OwnerAuthor

    Claude posting for Erik Darling.

    The real row counts are in, and the cap keeps about one row in four or five. Erik agreed to raising the cap, with plans rendered for at most 150 rows. The counts make one more choice worth making first, and that's below. This is for whoever builds it.

    Where 150 came from

    The cap appears with no comment in Lite's first release (v1.0.0, February). The Full edition's collector (install/10_collect_procedure_stats.sql) has no cap. Darling took the 150 with the shared collector extraction in July. Since #1959, the 150 also bounds how many plans render in one run.

    Measured

    • What was run: a read-only COUNT(*) over sys.dm_exec_procedure_stats, _trigger_stats and _function_stats, by last_execution_time window.
    • Where: the four busiest primaries by procedure CPU over 7 days, in the store where 95% of runs return exactly 150 rows.
    • When: 2026-10-07 at about 03:10 UTC, which is a busy period for this fleet.
    Server Rows that ran in the last 60 s (proc + trigger + function) Last 10 min (proc + trigger + function) Procedures, last 24 h Procedures in cache
    A 265 + 31 + 18 = 314 579 + 86 + 36 = 701 1,659 2,168
    B 380 + 30 + 21 = 431 657 + 56 + 42 = 755 1,717 2,655
    C 375 + 23 + 26 = 424 676 + 50 + 46 = 772 2,337 3,108
    D 455 + 35 + 29 = 519 674 + 79 + 41 = 794 1,795 2,955
    • The collector's filter is last_execution_time in the last 10 minutes, so each one-minute run is choosing 150 of about 700–800 candidate rows.
    • Of those, about 310–520 ran in the last minute. Those are the rows that can have a non-zero delta in a one-minute run.
    • The other 40% or so ran earlier in the 10 minutes. Their delta since the last run is 0, so storing them adds rows but no CPU.

    What raising the cap costs

    The choice to make first: keep only rows with work since the last run

    • The idea: a row with a zero delta contributes nothing to any CPU, duration or reads total. So the run could fetch the numbers for every candidate, compute the deltas as it does now, and store only the rows whose delta is non-zero.
      • The fetch has no TOP, or a safety TOP of several thousand. It returns numbers only, no plan and no text.
      • It renders plans for at most 150 of the stored rows, the top by in-interval work.
    • What that gives: about 310–520 stored rows per run here, instead of about 700–800, with the same totals. That's about 2–3.5× today's rows, not 5×.
    • One detail to keep: the per-key baseline (CollectorDeltaCalculator) must still be updated for a row that is fetched but not stored. Otherwise its next delta spans the skipped run. The stored interval already records the span, so a reader stays correct either way.
    • This is still Erik's call. The agreed plan (raise the cap, plans for at most 150) is a valid build as it is. This variant changes only which fetched rows are written.

    For whoever builds it

    1. Put the cap and the plan limit in one place in ProcedureStatsCollector.cs, and keep Lite's SQL shape in step. The collector is shared, so Lite.Tests runs on CI.
    2. Re-measure the store cost on a test server before the nightly that ships it. Measure rows per run, procedure_stats bytes per hour and run time.
    3. Then re-run the comparison from the issue body on the busy store. Darling's procedure CPU should move from 16% below the independent sampler to about equal.

  3. erikdarlingdata commented on Oct 7, 2026

    @erikdarlingdata
    erikdarlingdata
    on Oct 7, 2026
    OwnerAuthor

    Claude posting for Erik Darling.

    Decided (Erik, 2026-10-07): build the variant. The collector fetches every candidate row, computes the deltas as it does now, and stores only the rows whose delta is non-zero over a measured interval. Plans render for at most 150 of the stored rows, the top by in-interval work.

    • What's still stored: first sightings and counter resets. They report interval 0, which is new information, not idle.
    • What has to keep happening: the delta calculator is called for every fetched row, including the skipped ones, so each baseline stays fresh.
    • The precedent: this is the same rule PgStatementStatsCollector already uses. Its doc comment explains the baseline point in full.
    • The server-side fetch has no TOP of 150. It needs only a safety cap of several thousand rows, and it returns numbers only.
    • Readers: any reader that treats a missing minute as missing data, rather than as no work, needs checking. That covers charts, rollups and coverage checks. The PostgreSQL statement readers already handle it.
    • Before the nightly that ships it: measure rows per run, bytes per hour and run time on a test server. The expectation on the busiest primaries is about 310–520 stored rows per run, against about 700–800 candidates.
  4. erikdarlingdata
    added
    in-progressActively being worked by a local session or its agents (PR open or in flight)
    on Oct 7, 2026
  5. erikdarlingdata
    added 19 commits that reference this issue on Oct 7, 2026

    Lite procedure readers read a missing minute as no work: slicer count…

    9f978b6

    procedure_stats keeps every candidate that did work, with plans for a…

    f5672b2

    procedure_stats tests and comments follow the plan phase (#5449)

    714068e

    Darling procedure readers read a missing minute as no work: trend buc…

    3cf31e2

    Runner tests for procedure_stats' plan phase: a failed plan query shi…

    0d5b40b

    Lite procedure chart plots a quiet collector run as 0 (#5449)

    bda2093

    Procedure charts plot a quiet collector run as 0 and the Darling wind…

    1fcc6f4

    Procedure duration trend pin follows the stored CTE name (#5449)

    decb0d6

    Procedure history charts plot a quiet minute as 0; the Lite slicer ov…

    368899a

    Procedure hourly rollup trends count a quiet hour as zero work betwee…

    36cf55a

    Procedure window floor follows the log's retention cut, and history z…

    b0fb256

    WIP: Lite procedure trend on the run-based axis (#5449)

    411c8b0

    WIP: Lite procedure trend tests and pins (#5449)

    4818801

    Lite procedure duration trend reads the collector's runs as its time …

    9418928

    Procedure raw-tier trends read the collector's runs as their time axi…

    9604928

    Procedure hourly trend reads its idle hours from the collector's runs…

    889afc0

    Procedure trend and floor: a window with no row left keeps the retent…

    ac56162

    Procedure trend tests follow the run-axis denominator and the collect…

    b29a275

    Procedure stats keep every procedure that did work, with plans for at…

    c72f76e

  6. erikdarlingdata commented on Oct 7, 2026

    @erikdarlingdata
    erikdarlingdata
    on Oct 7, 2026
    OwnerAuthor

    Claude posting for Erik Darling. Fixed by #5463, merged to dev.

  7. erikdarlingdata
    closed this as completedon Oct 7, 2026
  8. erikdarlingdata
    removed
    in-progressActively being worked by a local session or its agents (PR open or in flight)
    on Oct 7, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

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