Skip to content

Ship and measure the cron-health sampling change #323

Open

Description

@HMarzban

Key: SPR-16 · Type: HITL · Part of: #327 · Blocked by: none · Checked against: 3bb26de

Problem

The worker calls get_cron_job_health every 60 s, and that one RPC is 10.7% of all prod DB time. It costs 3.7 s of DB time per hour: 120 calls/h at about 31 ms each [prod]. Sampling every 180 s instead cuts it to about 40 calls/h [pred].

The change is one constant, its comment and one doc line. It exists on the maintainer's machine only. It is not committed, not deployed and not measured.

Context

Tags: [prod] measured on prod on 2026-09-28 in a 69.8-minute window. [pred] predicted, not yet measured.

Why this RPC costs so much. public.get_cron_job_health() (packages/supabase/scripts/16-cron-jobs.sql ~63) reads every row of cron.job_run_details on each call. It groups by job and sorts the rows. The function is SECURITY DEFINER, and only service_role may execute it (~89-90).

Fact Value Tag
Calls per hour 120 (2 worker replicas × one call per 60 s) [prod]
DB time per hour 3,736 ms, which is 10.7% of all DB time (35.0 s/h) [prod]
Mean time per call now 31.0 ms (lifetime mean 103 ms) [prod]
cron.job_run_details live rows 25,898 (18 MB) [prod]
seq_tup_read on cron.job_run_details, lifetime 129,781,904,655 rows; this RPC is most of it (inferred, not split per caller) [prod]
All SQL on prod 35.0 s DB time/hour = 0.97% of one core [prod]
Saving after the change 80 calls/h and about 2,480 ms/h (7% of current DB time) [pred]
Money saved $0. Supabase bills compute by instance size, not by query work [docs]

The table held about 887,000 rows until 2026-09-21. On that day the new daily cleanup job deleted 861,693 rows. That is why the lifetime mean (103 ms) is much higher than the current mean (31 ms).

History. The 2026-07-17 audit moved this sample from every 15 s to every 60 s (commit 79cc9bede). This issue moves it from every 60 s to every 180 s.

Where the cadence lives. apps/hocuspocus.server/src/lib/workerMetricsSampler.ts:

  • QUEUE_METRICS_INTERVAL_MS = 15000 (~15) is the base tick.
  • CRON_HEALTH_SAMPLE_EVERY_TICKS is ~19 at HEAD (value 4) and ~20 in the maintainer's working tree (value 12).
  • sampleWorkerMetrics() (~139-145) calls sampleCronJobHealth() when metricsTick % CRON_HEALTH_SAMPLE_EVERY_TICKS === 0. The first tick is 0, so every worker start samples at once.
  • startWorkerMetricsSampling() runs from apps/hocuspocus.server/src/hocuspocus.worker.ts ~144.
  • The gauge is cron_job_last_success_timestamp_seconds with label jobname (src/lib/metrics.ts ~358-362).

Why two replicas. Prod runs 2 hocuspocus-worker replicas: docker-compose.prod.yml ~468 (replicas: 2 inside the hocuspocus-worker service, ~389). The deploy script calls deploy_service "hocuspocus-worker" 2 (.github/workflows/prod.docs.plus.yml ~688). Each replica samples on its own, so the call rate is 2 × (3600 / 180) = 40 calls/h.

Why 180 s is safe for the stale alert. The tightest alert is cron-stale-frequent in scripts/observability/grafana/provisioning/alerting/rules-supabase-jobs.yml (~86). It fires when time() - max by (jobname) (cron_job_last_success_timestamp_seconds{...}) is gt 900 (~124) for for: 5m. Its slowest job is process_document_views_queue, scheduled */10 * * * * (packages/supabase/scripts/09-document-views.sql ~872-874). Prometheus scrapes every 30 s (scripts/observability/prometheus/prometheus.yml ~2).

Part of the worst gauge age Seconds
Time between two runs of a */10 job 600
Worst sample lag at 180 s 180
Worst scrape lag at 30 s 30
Worst age 810, under the 900 s threshold with 90 s margin

So 180 s is the ceiling. Going past it breaks the margin for the */10 job.

Trade-off: the no-data (dead-man) window grows. On a failed RPC, sampleCronJobHealth() calls cronJobLastSuccess.reset() (~101). The series then stays absent until the next success. The cron-stale-* rules use noDataState: Alerting with for: 5m. Before this change, a replica restored the series 60 s after a failure. Now it takes 180 s. If NoData passes through the 5 m pending period, two failed samples in a row on both replicas can page (360 s > 300 s). Before, it took about five. So a Supabase blip of 3 to 6 minutes can now page. A long outage pages up to 2 minutes later, because the first failed sample comes later. Neither effect blocks the change.

Side note, not in scope. The cron-stale-frequent annotation says "runs every <=5m". That is wrong for the */10 job. The maintainer may fix the text separately.

The change, as it stands in the maintainer's working tree. A cold agent on a fresh clone will not see it. Apply this diff if main still has the old value (step 1).

--- a/apps/hocuspocus.server/src/lib/workerMetricsSampler.ts
+++ b/apps/hocuspocus.server/src/lib/workerMetricsSampler.ts
@@ -14,9 +14,10 @@ import { getServiceRoleClient } from './supabase'
 
 const QUEUE_METRICS_INTERVAL_MS = 15000
 
-// Cron health rides the queue tick at a slower cadence (60 s): every call
-// sweeps cron.job_run_details, and the cron-stale alerts only fire at >15m.
-const CRON_HEALTH_SAMPLE_EVERY_TICKS = 4
+// Cron health rides the queue tick at a slower cadence (180 s): every call
+// sweeps cron.job_run_details. The tightest stale alert is >15m on a */10 job,
+// and 10m + 3m sample lag + scrape stays under it.
+const CRON_HEALTH_SAMPLE_EVERY_TICKS = 12
 
 // DLQs included: their `waiting` depth is the alerting signal for poisoned jobs.
 const monitoredQueues = [

In apps/hocuspocus.server/CLAUDE.md (~162), replace the first line below with the second. It is one list item on one line.

-- **`get_cron_job_health` is a single-pass aggregate** (`scripts/16-cron-jobs.sql`) and the worker samples it every 60 s (`CRON_HEALTH_SAMPLE_EVERY_TICKS` in `workerMetricsSampler.ts`), not on the 15 s queue tick. Do not revert to per-job correlated subqueries or per-tick sampling — 26 seq scans of `cron.job_run_details` per call every 15 s was prod's #1 self-inflicted DB load (2026-07-17 audit).
+- **`get_cron_job_health` is a single-pass aggregate** (`scripts/16-cron-jobs.sql`) and the worker samples it every 180 s (`CRON_HEALTH_SAMPLE_EVERY_TICKS` in `workerMetricsSampler.ts`), not on the 15 s queue tick. Do not go past 180 s: the >15m stale alert covers a */10 job. Do not revert to per-job correlated subqueries or per-tick sampling — 26 seq scans of `cron.job_run_details` per call every 15 s was prod's #1 self-inflicted DB load (2026-07-17 audit).

No SQL changes. So no migration, no seed regeneration and no types regeneration.

What to do

  1. [agent] Check which state main is in. Run git grep -n "CRON_HEALTH_SAMPLE_EVERY_TICKS = " -- apps/hocuspocus.server/src. Ignore apps/hocuspocus.server/dist/: it is gitignored build output and still shows = 4.
    • If it prints = 12, the change is committed. Go to step 4. If the maintainer says it is already deployed, skip steps 4-5 and use the Before column in §Verification as the baseline.
    • If it prints = 4, apply both changes from §Context by hand. Change nothing else in either file.
  2. [agent] Run the checks. From the repo root: bun run --filter @docs.plus/hocuspocus typecheck, then bun run lint. Both must pass. Add no test: this is a constant, and tests are opt-in here.
  3. [maintainer] Commit through /commit-review. Run git diff --stat first. The two files above must hold only this change, or be staged by hunk. apps/hocuspocus.server/CHANGELOG.md holds other uncommitted maintainer edits; do not sweep them into this commit. A ### Changed line in that CHANGELOG is the maintainer's call. Suggested subject: perf(hocuspocus): sample cron health every 180s instead of 60s.
  4. [maintainer] Take the baseline on prod (read-only). Run the §Verification query. Wait one hour with no deploy, then run it again. The call delta should be about 120.
  5. [maintainer] Deploy the worker. Push so that the head commit subject is (build): back (grammar in .github/WORKFLOWS.md). Any app domain rolls out all five services, not only the worker. The rollout runs hocuspocus-worker first, at scale 2. Wait until both worker replicas are healthy.
  6. [maintainer] Measure after the deploy (read-only). Run the §Verification query. Wait one hour with no deploy or worker restart, then run it again. Each restart adds one extra call, because tick 0 samples.
  7. [maintainer] Keep the window clean. Do not reset pg_stat_statements during steps 4-6. The per-query reset in Find the cause of the 13-15 s realtime list_changes spikes #325 clears a list_changes control row and so breaks the total. The Postgres upgrade in Upgrade prod Postgres from 15.8.1.073 #322 restarts the database and may clear all stats. Run both after this measurement.
  8. [maintainer] Record the result on this issue: the four snapshots, the two deltas, and pass or fail. Then watch Grafana for 7 days (§Verification) and close.

Out of scope

Acceptance criteria

  • git grep -n "CRON_HEALTH_SAMPLE_EVERY_TICKS = " -- apps/hocuspocus.server/src prints = 12 on main.
  • The comment above the constant says 180 s and explains the 900 s margin.
  • apps/hocuspocus.server/CLAUDE.md (~162) says "every 180 s" and "Do not go past 180 s".
  • bun run --filter @docs.plus/hocuspocus typecheck and bun run lint pass.
  • The commit touches only these two files, plus an optional CHANGELOG line the maintainer chose.
  • A (build): back deploy with the change finished, and both worker replicas are healthy.
  • The after-deploy hourly delta of get_cron_job_health calls on prod is between 30 and 50. The baseline delta was about 120.
  • Mean ms per call stays near the baseline (about 31 ms).
  • For 7 days after deploy, cron-stale-frequent never goes Pending or Firing without a real stale job.

Verification

Prod query (read-only; [maintainer]). Run it at each snapshot in steps 4 and 6. Subtract calls and total_ms between two snapshots one hour apart.

select now(), r.rolname, s.queryid, s.calls,
       round(s.total_exec_time::numeric, 1) as total_ms
from pg_stat_statements s
join pg_roles r on r.oid = s.userid
where s.query ilike '%get_cron_job_health%'
   or s.query ilike '%get_pgmq_queue_metrics%'
   or (s.query ilike '%set_config(%' and r.rolname = 'service_role')
   or s.query ilike '%realtime.list_changes%';

-- Total for all statements, for the last table row.
select now(), sum(calls) as calls,
       round(sum(total_exec_time)::numeric, 1) as total_ms
from pg_stat_statements;

Sum the set_config rows if there is more than one.

Measure per hour Before [prod] Pass after [pred]
get_cron_job_health calls 120 about 40 (30-50)
get_cron_job_health DB ms 3,736 about 1,245
service_role REST requests (set_config rows) 2,074 about 1,994
Total DB ms, all statements 35,009 about 32,500 (Realtime varies with users)

get_pgmq_queue_metrics and realtime.list_changes are controls. Their rates should not change.

Prometheus ([maintainer]).

  • count by (jobname) (cron_job_last_success_timestamp_seconds) returns every pg_cron job right after deploy. So the series still exist.
  • max_over_time((time() - max(cron_job_last_success_timestamp_seconds{jobname="process_document_views_queue"}))[24h:30s]) stays under 900. The expected worst is about 810, plus the job's own run time.

Grafana ([maintainer]). For 7 days: cron-stale-frequent never goes Pending, and pgmq_oldest_message_age_seconds does not rise.

House rules

  • Bun only. Never run npm, yarn, pnpm or npx in this repo.
  • No commits unless the maintainer asks. The commit goes through /commit-review. No git add, git commit, git push or git stash by an agent.
  • Tests are opt-in. Do not add a test for a constant.
  • A push deploys only when its head commit subject starts with (build):. The worker deploys before hocuspocus-server.
  • Agents have no prod access. Every prod read is a [maintainer] step, and nothing in this issue writes to prod.
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

    Type

    No type

    Projects

    No projects

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions