diff --git a/packages/the-framework/src/daemon-tick.SPEC.md b/packages/the-framework/src/daemon-tick.SPEC.md index 0d741a4b0..2b497aba0 100644 --- a/packages/the-framework/src/daemon-tick.SPEC.md +++ b/packages/the-framework/src/daemon-tick.SPEC.md @@ -3,6 +3,7 @@ The daemon's one background clock: a single interval that runs a list of jobs, e ## Flows - A job's cadence is a small integer rather than a duration: the base interval is the finest cadence anything needs, and everything slower is that many ticks. +- A tick is counted whenever the clock comes round, whether or not a turn could start: a job that runs long costs its own next turn and nothing else, and every other job's cadence keeps to the wall clock. - A missed turn is skipped, never queued: a slow job comes back to the next turn, not to a backlog of them. - A job that throws costs its own turn and nothing else, and says so with its name. - The first tick fires at start-up rather than an interval later; a job that only makes sense once the daemon has been up says so. @@ -13,6 +14,7 @@ The daemon's one background clock: a single interval that runs a list of jobs, e - One clock rather than a timer per sweep: a single schedule gives one place to look when "nothing is happening" turns out to be a sweep that was not running. - Tick counts rather than durations keep the ratios exact by construction, where separate timers drift. +- A tick that no turn could take is still counted, because counting only the turns that ran let a single slow job stretch every cadence in the daemon by its own duration: while one project's data sync was failing slowly against a remote it could not reach, the ten-minute cloud-work pass came round every twenty-six minutes, and every other sweep with it. - A throwing job is named because a sweep failing silently is indistinguishable from one that was never scheduled. - The start-up tick exists because the case most of these jobs exist for is a machine that was off while something happened. - A tick you can await to completion is what makes the schedule testable without waiting on wall-clock time. diff --git a/packages/the-framework/src/daemon-tick.test.SPEC.md b/packages/the-framework/src/daemon-tick.test.SPEC.md index 243a5c2f8..fdc28f19d 100644 --- a/packages/the-framework/src/daemon-tick.test.SPEC.md +++ b/packages/the-framework/src/daemon-tick.test.SPEC.md @@ -1,4 +1,4 @@ -Covers the daemon's clock: a job running every Nth tick with missed turns skipped rather than queued, opting out of the start-up tick, a throwing job costing only its own turn and being named in the log, jobs running one at a time in order, overlapping ticks joining the one in flight, a stopped clock doing nothing further, and stopping resolving only once the turn already in flight has finished. +Covers the daemon's clock: a job running every Nth tick with missed turns skipped rather than queued, opting out of the start-up tick, a throwing job costing only its own turn and being named in the log, jobs running one at a time in order, overlapping ticks joining the one in flight, a tick that came round mid-turn still counting towards every cadence, a stopped clock doing nothing further, and stopping resolving only once the turn already in flight has finished. ## Before modifying/creating SPEC.md files diff --git a/packages/the-framework/src/daemon-tick.test.ts b/packages/the-framework/src/daemon-tick.test.ts index 903a9edf9..f80387850 100644 --- a/packages/the-framework/src/daemon-tick.test.ts +++ b/packages/the-framework/src/daemon-tick.test.ts @@ -139,3 +139,47 @@ test('stopping waits out the turn already in flight, rather than only the next o assert.equal(finished, true, 'stop resolved only once the sweep had finished') await turn }) + +test('a firing that lands mid-turn still counts, so one slow job cannot stretch every other cadence', async () => { + // #1607: a cadence was measured in turns that *ran*, and a firing arriving mid-turn joined the + // one in flight without being counted anywhere. A job that blocked for minutes — the case seen + // live was a data sync failing slowly against an unreachable remote — therefore pushed every + // other `every: N` job out by its own duration: a ten-minute pass came round every twenty-six. + let rare = 0 + let slowTurns = 0 + let releaseSlow = (): void => {} + const blocked = new Promise(resolve => { + releaseSlow = resolve + }) + const tick = startDaemonTick({ + intervalMs: 5, + log: () => {}, + jobs: [ + { name: 'rare', every: 5, run: async () => void rare++ }, + { name: 'slow', run: async () => void (slowTurns++ === 0 && (await blocked)) }, + ], + }) + try { + // The constructor's tick 0: `rare` takes its start-up turn, then `slow` holds the turn open. + const turn0 = tick.tick() + await new Promise(resolve => setTimeout(resolve, 50)) + assert.equal(rare, 1, 'only the start-up turn so far — the clock is still inside tick 0') + + // ~10 firings came round at 5ms apart while that one turn was in flight. + releaseSlow() + await turn0 + await tick.tick() + + // Well past tick 5, so `rare` is due now — not five *further* turns from now, which is what + // counting only the turns that ran used to mean. + assert.equal(rare, 2, 'the firings that landed mid-turn counted towards the cadence') + // And each job took exactly one further turn: the ones they missed are skipped, never queued + // up to be worked through one after another. + assert.equal(slowTurns, 2, 'one further turn, not one per firing that was missed') + } finally { + // Before `stop()`, which waits out the turn in flight: a turn still blocked here would + // deadlock the shutdown rather than fail the assertion above. + releaseSlow() + await tick.stop() + } +}) diff --git a/packages/the-framework/src/daemon-tick.ts b/packages/the-framework/src/daemon-tick.ts index ae1447675..58b0cf4e3 100644 --- a/packages/the-framework/src/daemon-tick.ts +++ b/packages/the-framework/src/daemon-tick.ts @@ -20,8 +20,11 @@ export interface TickJob { /** For the log line when it throws. */ name: string /** - * Ticks between turns. `1` is every tick, `20` is every twentieth. Its own turn is *skipped* - * rather than queued, so a slow job never accumulates a backlog of missed turns to work through. + * Ticks between turns. `1` is every tick, `20` is every twentieth. A tick is the interval + * coming round, not a turn that ran, so a slow job on the same clock cannot stretch this out. + * + * Its own turn is *skipped* rather than queued, so a slow job never accumulates a backlog of + * missed turns to work through. */ every?: number /** Run one turn. Awaited, so a long job holds the tick rather than overlapping the next one. */ @@ -58,6 +61,11 @@ export interface DaemonTickOptions { log: (message: string) => void } +/** Ticks between a job's turns, defaulted and floored. */ +function cadence(job: TickJob): number { + return Math.max(1, job.every ?? 1) +} + /** * Start the clock and return the handle that stops it. * @@ -71,17 +79,34 @@ export interface DaemonTickOptions { */ export function startDaemonTick(opts: DaemonTickOptions): DaemonTick { let stopped = false - let count = 0 + /** + * Which tick is running now. Advanced by {@link elapsedWhileBusy} as well as by one, so it + * stays a count of how many times the interval has *come round* rather than how many turns + * happened to run (#1607). + */ + let tickNow = -1 + /** + * Interval firings that arrived while a turn was in flight. Time passed for them, so they count + * towards every cadence — the turn they would each have had is folded into the next one. + */ + let elapsedWhileBusy = 0 let inflight: Promise | undefined + /** + * The tick each job last took a turn on, seeded so tick 0 is already due for a job that wants + * the start-up turn and one whole cadence away for a job that sits it out. + */ + const lastTurn = opts.jobs.map(job => (job.onStart === false ? 0 : -cadence(job))) - const runTick = async (): Promise => { - const n = count++ - for (const job of opts.jobs) { + const runTick = async (n: number): Promise => { + for (const [index, job] of opts.jobs.entries()) { if (stopped) return - const every = Math.max(1, job.every ?? 1) - // Offset by one so a job with `every: 20` runs on tick 0 too when it wants a start-up turn, - // and is skipped on tick 0 when it does not. - if (n === 0 ? job.onStart === false : n % every !== 0) continue + // Ticks *since this job's own last turn*, rather than `n % every`: when the clock jumps + // over the tick a job's cadence would have landed on, the job is due at the next turn + // instead of waiting a whole further cadence for the modulo to come round again. + if (n - lastTurn[index]! < cadence(job)) continue + // Claimed before the run, not after: a missed turn is skipped rather than queued, and a job + // that throws has still had its turn. + lastTurn[index] = n try { await job.run() } catch (err) { @@ -92,14 +117,30 @@ export function startDaemonTick(opts: DaemonTickOptions): DaemonTick { const tick = (): Promise => { if (stopped) return Promise.resolve() - inflight ??= runTick().finally(() => { + // A caller that arrives mid-turn joins it without moving the clock: `tick()` means "run a + // turn now" — the daemon's shutdown and the tests drive it, and neither is elapsed time. + // Only the interval is, and it says so through `elapsedWhileBusy`. + if (inflight) return inflight + tickNow += 1 + elapsedWhileBusy + elapsedWhileBusy = 0 + inflight = runTick(tickNow).finally(() => { inflight = undefined }) return inflight } void tick() - const timer = setInterval(() => void tick(), opts.intervalMs ?? DAEMON_TICK_MS) + const timer = setInterval(() => { + // The clock moved whether or not a turn can start. Counting a firing that lands on a busy + // daemon is the whole point: without it a long job — a data sync failing slowly against an + // unreachable remote — stretched every `every: N` cadence by its own duration, because a + // cadence was measured in turns that ran rather than in time that passed (#1607). + if (inflight) { + elapsedWhileBusy++ + return + } + void tick() + }, opts.intervalMs ?? DAEMON_TICK_MS) timer.unref?.() return { tick,