How to check cron schedule drift

A drifting schedule produces runs that happen, late. Record the instant the expression named and the instant work began, then print the difference for every run. In the window below the median is 9 ms while the last run starts 10666 ms after its due instant, and only the per-run column shows it.

Why check this

Run this after a change that makes a job slower, after the scheduler moves onto a shared host, and on staging sign-off for any job with a deadline. Drift is invisible to a presence audit: every run is recorded and every run returns ok. A nightly export that has to reach a partner by 06:00 starts at 05:58 in week one and after 06:00 in week six, with no failed status in between. The partner notices first.

Prerequisites

• Node 22 and cron-parser, installed with npm i cron-parser@5.4.0. Version 5.4.0 produced every figure here and is the parser the tool above runs.
• A ledger with two timestamps per run. One answers whether the job ran; the difference between two answers when.
• The crontab(5) manual, and the timezone the scheduler resolves the expression in.
• No cron daemon and no container are used here. The targets are the four Node programs below, run on Windows 11 with Node 22.23.2. The idle timer floor on this host is near 15 ms and yours will differ.

// timer-drift.mjs <anchored|chained> <intervalMs> <ticks>
const [mode, intervalArg, ticksArg] = process.argv.slice(2);
const interval = Number(intervalArg);
const ticks = Number(ticksArg);
const t0 = Date.now();
const late = [];
let k = 0;

function report(k, now) {
  const due = t0 + k * interval;
  late.push(now - due);
  if (k % 25 === 0 || k === ticks) {
    console.log(`tick ${String(k).padStart(3)} late ${String(now - due).padStart(5)} ms`);
  }
}

function done() {
  const elapsed = Date.now() - t0;
  console.log(
    `${mode} interval ${interval} ms ticks ${ticks} nominal ${interval * ticks} ms elapsed ${elapsed} ms final lateness ${late[late.length - 1]} ms`
  );
}

if (mode === 'chained') {
  const step = () => {
    k += 1;
    report(k, Date.now());
    if (k < ticks) setTimeout(step, interval);
    else done();
  };
  setTimeout(step, interval);
} else {
  const step = () => {
    k += 1;
    report(k, Date.now());
    if (k < ticks) setTimeout(step, t0 + (k + 1) * interval - Date.now());
    else done();
  };
  setTimeout(step, t0 + interval - Date.now());
}

// interval-drift.mjs <intervalMs> <ticks>
const interval = Number(process.argv[2]);
const ticks = Number(process.argv[3]);
const t0 = Date.now();
let k = 0;
const id = setInterval(() => {
  k += 1;
  const late = Date.now() - (t0 + k * interval);
  if (k % 25 === 0 || k === ticks) console.log(`tick ${String(k).padStart(3)} late ${String(late).padStart(5)} ms`);
  if (k === ticks) {
    clearInterval(id);
    console.log(`setInterval ${interval} ms ticks ${ticks} nominal ${interval * ticks} ms elapsed ${Date.now() - t0} ms final lateness ${late} ms`);
  }
}, interval);

// cron-runner.mjs <queued|anchored> <expression> <timezone> <runs> <ledger>
import { appendFileSync } from 'node:fs';
import { CronExpressionParser } from 'cron-parser';

const [mode, expr, tz, runsArg, ledger] = process.argv.slice(2);
const jobMs = Number(process.env.JOB_MS ?? 40);
const slowAfter = Number(process.env.SLOW_AFTER ?? Infinity);
const slowMs = Number(process.env.SLOW_MS ?? jobMs);
const sleep = (ms) => new Promise((ok) => setTimeout(ok, Math.max(0, ms)));

console.log(`runner pid ${process.pid} mode ${mode} expression ${expr} zone ${tz}`);

let it = CronExpressionParser.parse(expr, { tz });
for (let n = 1; n <= Number(runsArg); n++) {
  const due = it.next().toDate();
  await sleep(due - Date.now());
  const startedAt = new Date();
  await sleep(n > slowAfter ? slowMs : jobMs);
  appendFileSync(
    ledger,
    JSON.stringify({ n, due: due.toISOString(), startedAt: startedAt.toISOString(), lateMs: +startedAt - +due }) + '\n'
  );
  if (mode === 'anchored') it = CronExpressionParser.parse(expr, { tz, currentDate: new Date() });
}

// drift-report.mjs <ledger> [tail]
import { readFileSync } from 'node:fs';

const [ledger, tailArg] = process.argv.slice(2);
const rows = readFileSync(ledger, 'utf8').trim().split('\n').map((l) => JSON.parse(l));
const late = rows.map((r) => r.lateMs).sort((a, b) => a - b);
const pct = (p) => late[Math.min(late.length - 1, Math.ceil((p / 100) * late.length) - 1)];

for (const r of rows.slice(-Number(tailArg ?? rows.length))) {
  console.log(`run ${String(r.n).padStart(2)} due ${r.due.slice(11, 23)} started ${r.startedAt.slice(11, 23)} late ${String(r.lateMs).padStart(6)} ms`);
}
console.log(
  `runs ${rows.length} p50 ${pct(50)} ms p90 ${pct(90)} ms max ${late[late.length - 1]} ms last ${rows[rows.length - 1].lateMs} ms`
);

The expressions below fire every second, so the page reproduces in under two minutes. A production schedule is minute-level and the arithmetic is the same.

Steps

1. 1

   Step 1.

   Fire 200 times at a nominal 20 ms, each delay measured from the previous firing. The run takes 6 seconds.

   node timer-drift.mjs chained 20 200
   

   tick  25 late   274 ms
   tick  50 late   544 ms
   tick  75 late   811 ms
   tick 100 late  1084 ms
   tick 125 late  1369 ms
   tick 150 late  1637 ms
   tick 175 late  1906 ms
   tick 200 late  2173 ms
   chained interval 20 ms ticks 200 nominal 4000 ms elapsed 6174 ms final lateness 2173 ms

   Lateness climbs about 270 ms every 25 firings and never returns. A 20 ms delay costs about 31 ms here, and the excess carries into the next delay.

2. 2

   Step 2.

   Fire 200 times at the same nominal interval, each delay measured from a fixed start instant.

   node timer-drift.mjs anchored 20 200
   

   tick  25 late    10 ms
   tick  50 late    15 ms
   tick  75 late     7 ms
   tick 100 late    14 ms
   tick 125 late     4 ms
   tick 150 late    11 ms
   tick 175 late    50 ms
   tick 200 late     9 ms
   anchored interval 20 ms ticks 200 nominal 4000 ms elapsed 4009 ms final lateness 9 ms

   Same timer and the same 200 firings, and the error stays at the floor. One firing measured 50 ms and the next was back under 15 ms, because each delay is recomputed against the clock.

3. 3

   Step 3.

   Check whether setInterval behaves as a period rather than a delay.

   node interval-drift.mjs 20 200
   

   tick  25 late   268 ms
   tick  50 late   532 ms
   tick  75 late   798 ms
   tick 100 late  1069 ms
   tick 125 late  1339 ms
   tick 150 late  1615 ms
   tick 175 late  1888 ms
   tick 200 late  2152 ms
   setInterval 20 ms ticks 200 nominal 4000 ms elapsed 6153 ms final lateness 2152 ms

   The shape matches step 1 to within 1 percent. Replacing a chained setTimeout with setInterval fixes nothing.

4. 4

   Step 4.

   Measure the same chained form at a longer interval.

   node timer-drift.mjs chained 1000 10
   

   tick  10 late    95 ms
   chained interval 1000 ms ticks 10 nominal 10000 ms elapsed 10098 ms final lateness 95 ms

   Ten firings cost 95 ms, about 9.5 ms each. Drift is that per-firing cost times the number of firings, so a frequent schedule reaches a visible number first.

5. 5

   Step 5.

   Start a cron runner whose job outlasts its interval, and note its process id. It runs for 43 seconds.

   JOB_MS=40 SLOW_AFTER=22 SLOW_MS=2500 node cron-runner.mjs queued '* * * * * *' UTC 30 ramp.jsonl
   

   runner pid 32200 mode queued expression * * * * * * zone UTC

   The first 22 runs take 40 ms on a one second schedule. From run 23 the job takes 2500 ms, and the runner takes each due instant in order rather than dropping it.

6. 6

   Step 6.

   Print the last ten runs of that ledger.

   node drift-report.mjs ramp.jsonl 10
   

   run 21 due 18:43:22.000 started 18:43:22.002 late      2 ms
   run 22 due 18:43:23.000 started 18:43:23.000 late      0 ms
   run 23 due 18:43:24.000 started 18:43:24.006 late      6 ms
   run 24 due 18:43:25.000 started 18:43:26.524 late   1524 ms
   run 25 due 18:43:26.000 started 18:43:29.042 late   3042 ms
   run 26 due 18:43:27.000 started 18:43:31.565 late   4565 ms
   run 27 due 18:43:28.000 started 18:43:34.093 late   6093 ms
   run 28 due 18:43:29.000 started 18:43:36.621 late   7621 ms
   run 29 due 18:43:30.000 started 18:43:39.150 late   9150 ms
   run 30 due 18:43:31.000 started 18:43:41.666 late  10666 ms
   runs 30 p50 9 ms p90 6093 ms max 10666 ms last 10666 ms

   Each start slips about 1520 ms further than the last, the job duration minus the interval. Read the column, not the summary under it: p50 9 ms describes 22 runs that are over, and run 30 finishes 13166 ms after the instant it was asked for.

7. 7

   Step 7.

   Run the same slow job through a runner that re-reads the clock after every run.

   JOB_MS=40 SLOW_AFTER=4 SLOW_MS=2500 node cron-runner.mjs anchored '* * * * * *' UTC 12 anchored.jsonl
   

   runner pid 8796 mode anchored expression * * * * * * zone UTC

   The next instant is parsed with currentDate: new Date() once the job returns, so instants that passed during the job are never scheduled.

8. 8

   Step 8.

   Report that ledger and compare the due column with step 6.

   node drift-report.mjs anchored.jsonl
   

   run  1 due 18:43:50.000 started 18:43:50.015 late     15 ms
   run  2 due 18:43:51.000 started 18:43:51.009 late      9 ms
   run  3 due 18:43:52.000 started 18:43:52.012 late     12 ms
   run  4 due 18:43:53.000 started 18:43:53.004 late      4 ms
   run  5 due 18:43:54.000 started 18:43:54.010 late     10 ms
   run  6 due 18:43:57.000 started 18:43:57.003 late      3 ms
   run  7 due 18:44:00.000 started 18:44:00.007 late      7 ms
   run  8 due 18:44:03.000 started 18:44:03.005 late      5 ms
   run  9 due 18:44:06.000 started 18:44:06.004 late      4 ms
   run 10 due 18:44:09.000 started 18:44:09.010 late     10 ms
   run 11 due 18:44:12.000 started 18:44:12.011 late     11 ms
   run 12 due 18:44:15.000 started 18:44:15.009 late      9 ms
   runs 12 p50 9 ms p90 12 ms max 15 ms last 9 ms

   Lateness never passes 15 ms, and from run 6 the due instants are three seconds apart on a one second schedule. Two thirds of the work is gone and the lateness column reads healthy.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | Lateness in single-digit milliseconds with no trend | The next instant is computed from the schedule and the runs do not move it | Record that floor as this host's baseline before you set an alert | | Lateness rising by a similar amount every run | The next start is computed from the previous start or the previous finish | Recompute from the expression, as step 2 and step 7 do | | The rise per run equals job duration minus interval | The job outlasts its interval and the runner queues the instants | Shorten the job, widen the interval, or give the work more than one consumer | | p50 in milliseconds and max in seconds in one window | The window holds a ramp that the median averages away | Read the last run and the trend, not the percentile | | Lateness flat while consecutive due values are further apart than the expression | The runner re-anchors after each job and drops the instants that passed | Count the instants too: Why is my cron job not running | | One late run with its neighbours on time | A single stall, not drift | Correlate that instant with How to measure event loop lag |

Common mistakes

What to check next

• Why is my cron job not running: the instants that produced no run at all.
• How to check if a cron job ran: one instant rather than a window.
• How to check if a cron job is still running: step 5 without the serial constraint.
• How to validate cron expression: where the due column comes from.
• How to measure event loop lag: the cause behind one late run among flat ones.

FAQ

What counts as cron schedule drift?

A run that happened at the wrong time. The row exists, the status is ok, and the start is later than the instant the expression named. One subtraction per run measures it, startedAt minus due.

Why does the same job start later every day?

Because the next run is computed by adding an interval to the last one. Each firing carries the previous error forward, so drift is the per-firing cost times the number of firings: 9.5 ms per firing in step 4.

Does drift mean the server clock is wrong?

Not in any run on this page. The system clock was never touched and the last run still began 10666 ms after its due instant. Check the arithmetic that produced the next instant first.

Should I measure lateness or count the runs?

Both. Step 8 shows lateness under 15 ms on a runner that skipped two instants out of every three. Lateness describes the runs in the ledger, and a count against the expression finds the ones that are not.

Verified