Skip to content

fix(rescore): pace a backgrounded pass under iOS's CPU limit instead of deferring it - #2280

Closed
Iskrata wants to merge 2 commits into
ryanbr:mainfrom
Iskrata:fix/rescore-background-cpu-pacing
Closed

Iskrata wants to merge 2 commits into
ryanbr:mainfrom
Iskrata:fix/rescore-background-cpu-pacing

Conversation

@Iskrata

@Iskrata Iskrata commented Sep 16, 2026

Copy link
Copy Markdown

Stacked on #2279. Review only the last commit (fix(rescore): pace a backgrounded pass…).

What this PR does

#1538 read the killed background passes as work that could not finish inside one wake, so it deferred any pass slower than 20 s to a processing task. The device's own crash reports point to a different cause: iOS's background CPU limit.

Across five nights, one iPhone 16 (WHOOP 5.0) logged 26 NOOP Staging.cpu_resource_fatal-*.ips reports, each one:

CPU: 48 seconds cpu time over 52 seconds (93% cpu average), exceeding limit of 80% cpu over 60 seconds
Action taken: Process killed

On that install a cold pass is about 144 s of near-continuous CPU (re-score: done — scored 21 night(s) in 144311 ms, dayCache reused=0/21). Every background attempt was killed about 52 s in, including the processing-task attempts it had been deferred to, which fired every ~30 min between 00:28 and 04:00. Deferring only moved where the kill happened. The night's scores appeared when the app was next opened.

The fix: in the background, a pass now rests after each night, in both the pass-1 and score2 loops, for as long as that night's work took (capped at 30 s), which keeps it near 50% CPU. A suspension between rests doesn't kill the pass; it picks up on the next wake, so a pass longer than any single wake still completes.

Once a pass can't be killed for running long, its duration is no longer a reason to defer, so the measurement rule is removed:

Type of change

  • Bug fix

How it was tested

  • RescoreBackgroundPolicyTests (rewritten around the new rules and pacing), RescoreBackgroundSchedulerTests (updated, plus a running-pass case), IntelligenceForcedRescoreRearmTests: 36 tests pass.
  • NOOPiOS builds for device and is installed on the reporting iPhone.
  • Draft until an overnight run confirms: no new cpu_resource_fatal reports, re-score: done while backgrounded, and the night in Apple Health by morning without opening the app. I'll post the strap-log lines and crash-report listing here.

Checklist

  • No new build warnings introduced
  • Follows the conventions in docs/CONTRIBUTING.md (doc_comment_lint.py clean; parity-governance suite and ratchet clean)
  • I did not commit generated output (Strand.xcodeproj/) or any secrets/keystores

Related issues

Refs #1538, #1681, #2238

…and stop a suspended pass deferring every one after it

A backgrounded offload defers its re-score to a processing task (ryanbr#1538) and then runs the Apple Health
write-back straight away, before anything new is scored. The deferred pass published the widget snapshot
when it finished but never Apple Health, so last night's sleep and vitals reached Health only on a later
foreground, typically mid-day.

The pass also timed itself with `Date()`, which counts the minutes a suspended process spends asleep. One
overnight pass on a sleeping phone banked 19 003 s as its cost, and every background re-score after it
deferred on that figure. It now times on the uptime clock, as the rest of the engine's probes already do,
and the policy reads a measurement past 30 minutes as unknown, which also clears a value an install banked
before this change.

The processing task's expiry is now logged. A strap log that simply stopped at 00:01 had no way to say
whether the pass was cut off there.
…of deferring it

ryanbr#1538 read the killed background passes as work that could not finish inside a wake, and deferred any
pass whose last completed run took over 20 s to a processing task. The on-device crash reports say
otherwise: 26 `cpu_resource_fatal` kills on one iPhone in five nights ("48 seconds cpu time over 52
seconds ... exceeding limit of 80% cpu over 60 seconds"), each about 52 s into a pass. A cold pass is
~144 s of near-continuous CPU on that install (`re-score: done — scored 21 night(s) in 144311 ms`,
`dayCache reused=0/21`), so every attempt in the background was killed, including the processing task
it was deferred to. The deferral only moved the kill, and the night's scores reached the phone when the
app was next opened.

A backgrounded pass now rests after each night, in both loops, for as long as the night took (capped at
30 s), holding it near 50% CPU. Suspension between rests does not kill it; it resumes on the next wake,
so a pass longer than any single wake completes. With that, how long a pass takes stops being a reason
to defer an offload, and the measurement rule is gone:

- a real update (an offload) runs in the background, paced;
- a pass owed from a KILLED attempt still defers, as before;
- a pass running in this process is not a killed one: its own started-mark reads as owed, and deferring
  on it recorded a newer debt the running pass could not settle (ryanbr#1681), so every later offload deferred.
  The trigger now reaches the engine, which re-arms one follow-up pass;
- the backstop tick no longer runs in the background at all, since a paced pass costs minutes and every
  real update runs its own;
- a processing task that finds a pass already running leaves it to settle its own debt.

The measured duration is still banked and logged.
@ryanbr

ryanbr commented Sep 17, 2026

Copy link
Copy Markdown
Owner

Reviewed the top commit only, as asked. The diagnosis is well evidenced and the pacing is carefully built. Notes below are questions rather than objections, and the draft gate is in the right place.

What convinces

26 cpu_resource_fatal reports all reading the same shape, with a 144 s cold pass against a kill at ~52 s, is about as direct as evidence gets here. It also explains why the #1538 remedy did not work: deferring moved WHERE the kill happened rather than preventing it, and the processing-task attempts were killed on the same limit. That is the kind of conclusion that is easy to reach after the fact and hard to reach first.

The 30 s cap earns its comment. DispatchTime.uptimeNanoseconds keeps advancing while the process is merely suspended, so an uncapped rest would make an already-idle pass rest for time it did not spend working. Catching that is the sort of detail that usually shows up later as "why is this so slow".

paceIfBackgrounded reading isBackgrounded through MainActor.run per unit, rather than sampling once at the start, is also right: a pass that begins in the foreground and is backgrounded mid-run starts pacing from that point.

The load-bearing assumption

A suspension between rests doesn't kill the pass; it picks up on the next wake, so a pass longer than any single wake still completes.

This is the claim the whole design rests on, and it is the one I cannot check from the code. Suspension is indeed survivable, but a pass running under an expiring BGProcessingTask, or past beginBackgroundTask's grant, is a different matter, and withAssertion's own comment says the heavy loop runs detached and cannot be cancelled from the expiry handler. So there are two failure shapes worth separating in the overnight run:

  1. the pass is suspended and genuinely resumes, which is what you predict;
  2. the assertion expires, the expiry handler logs and escalates, and the pass continues detached past its grant.

Both leave "no cpu_resource_fatal" true, and only the first means a backgrounded pass reliably finishes. Worth capturing whether the expiry handler fired at all on the good night.

Wall clock

At 1:1 pacing a 144 s pass becomes roughly 288 s of wall clock before suspensions, and each of 21 nights can rest up to 30 s. Fine for a processing task; much less so for a short refresh wake. It would help to say which wake type the paced pass is expected to complete under, since "it resumes next wake" is doing a lot of work if the answer is usually "it never finishes in one".

The part I would watch hardest

Removing duration as a reason to defer takes away the safety net at the same time as adding the thing that replaces it. If pacing turns out not to hold the limit on some device (a slower phone, a larger history, a pass that is more CPU-dense per night than this one), there is no longer a deferral path to catch it, and the symptom returns as kills rather than as delays. A line in the log when a pass exceeds some multiple of its expected wall clock would make that visible without reintroducing the rule.

Draft gate

Holding until an overnight run shows no new crash reports, re-score: done while backgrounded, and the night in Health by morning is exactly right, and the three criteria are the right three. Ping when it lands and I will look again.

Also worth noting for whoever sequences this: it is stacked on #2279, so that one needs to go first.

@ryanbr
ryanbr marked this pull request as ready for review September 17, 2026 08:02
@ryanbr

ryanbr commented Sep 17, 2026

Copy link
Copy Markdown
Owner

Good news first: the parent has landed. #2279 is on main as 2eafe4b0b, so this is no longer stacked.

Could you rebase onto current main before this goes any further? Two reasons, and the second is the one that matters.

The parent went in as a SQUASH. The commit this branch carries (f732278c5) is therefore not an ancestor of main; main has the squashed equivalent under a different hash. Merging as-is would re-apply the parent's changes on top of the version already there. git merge-tree against current main reports three conflicts, so it would not go in quietly, but it is worth naming because a stacked branch that merges CLEANLY after a squash is the genuinely dangerous case: the content lands twice with nothing to show for it.

The branch point is also well behind main now. Diffing main.. this branch currently reads as deleting AGENTS.md, restoring CLAUDE.md, and removing HealthExportMerge.swift, WorkoutNamespaceTests, WorkoutScopeTests, the i18n audit rule and its tests, the Coach master switch and its strings, and the motion-trace hoist. About 2,110 deletions in total.

To be clear, this PR is not proposing any of that. It is what a stale branch point looks like from main's side, and it is exactly the shape that lands as a silent revert if someone merges on a green tick without reading the file list. A rebase makes the diff say what the change actually is: one pacing commit.

Worth knowing too: the 4/4 green on fad0085a5 was measured against the old base, so it does not describe the merge result either way. A rebase re-runs it honestly.

Nothing about the change itself is in question here. The review notes on the pacing still stand, as does the draft gate you set for the overnight run, and I would still like the expiry-handler question answered from that night: whether the pass genuinely resumed after suspension, or ran on detached past its grant. "No cpu_resource_fatal reports" reads the same either way, and only the first means a backgrounded pass reliably finishes.

@ryanbr

ryanbr commented Sep 17, 2026

Copy link
Copy Markdown
Owner

Landed as 65fde529f, via #2296.

To explain the detour rather than leave it looking like your PR was bypassed: this branch was stacked on #2279, which merged as a SQUASH, so its parent commit was not an ancestor of main. Combined with a branch point well behind main, the diff from main's side read as roughly 2,110 deletions, and git merge-tree reported conflicts. Rather than ask you for a round trip, I cherry-picked the single pacing commit onto current main, which gave what the change actually is: 6 files, +142/-134.

Your authorship is intact on the merged commit, I was only the committer, and I changed nothing in it. Verified before merging that the rebased hunks were byte-identical to yours and that the auto-merge had not disturbed anything in the files main had moved under you.

Closing this one as superseded rather than stale.

Two things carried into the squash message so they do not disappear with this PR:

  1. The overnight confirmation you set as your own gate was never posted. The question I would still like answered from that night is whether the assertion expiry handler fired. "No cpu_resource_fatal reports" reads the same whether the pass genuinely resumed after suspension or ran on detached past its grant, and only the first means a backgrounded pass reliably finishes. If the night has since run, that result is still worth posting.

  2. Removing duration-based deferral withdraws the safety net at the same moment its replacement arrives. If pacing does not hold the limit on a slower phone or a denser history, the symptom returns as process kills rather than delays, with nothing behind it.

Excellent diagnosis on this one. Reading 26 crash reports against a 144 s pass and concluding that the earlier remedy had only moved where the kill happened is the part that was hard to get right.

@Iskrata

Iskrata commented Sep 17, 2026

Copy link
Copy Markdown
Author

Thanks for landing it via #2296, and for checking the hunks were byte-identical. Here is the overnight result I owed you, with what it does and does not settle.

What the night showed (paced build installed 2026-09-16 evening, one iPhone 16):

  • No cpu_resource_fatal after install. The last one is from 2026-09-16 11:37, before the paced build; the previous five nights had 26.
  • Two passes completed while backgrounded, back to back, in one process (launched 00:43, still running at 09:46): scored 21 night(s) in 8813251 ms at 06:53 and 2345035 ms at 08:53.
  • Neither pass logged background time expired mid-pass. The strap log for that session was head-clipped (1,000 of 2,000 lines kept), so "no expiry" is not proven for the whole 2 h 27 min.
  • CPU versus elapsed: a cold pass is ~144 s of CPU in the foreground, against 8,813 s of uptime here. That can only mean the pass spent most of the night suspended or starved between short wakes, not running on past its grant. Your case 1, as far as the evidence goes. But I would rather measure it than infer it, so feat(rescore): log a pass's CPU time and assertion expiries beside its elapsed time #2297 logs cpu=, elapsed= and assertionExpired= beside every re-score: done. I'll post the first overnight line from it here.

Why those passes were hours long at all turned out to be a separate problem, now #2293:

  • The day cache was dropped on every pass. Tonight's session, re-banked by each sync, moved sleepConsistency / habitualMidsleep in the cache signature.
  • Every pass re-read all 21 sleep-to-sleep cycles' heart rate.

Replayed against a copy of that phone's database: a pass with nothing new went from 96 s to 2.9 s, and one with a minute of new heart rate from 16 s to 7.9 s. So pacing was holding the CPU limit, but the work being paced was mostly redundant.

On the safety net: agreed that duration-based deferral is gone. Two things now make its absence visible:

One more data point: that phone was running a Debug (-Onone) build during all of this. Release will be considerably cheaper per pass. The kills and the redundant work were real regardless, but that is worth knowing when reading the absolute numbers.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants