Skip to content

Count and time the per-day probe queries - #2024

Merged
ryanbr merged 1 commit into
mainfrom
diag/store-probe-tally
Sep 9, 2026
Merged

ryanbr merged 1 commit into
mainfrom
diag/store-probe-tally

Conversation

@ryanbr

@ryanbr ryanbr commented Sep 9, 2026

Copy link
Copy Markdown
Owner

Why

With #2023 in, the steps-calibration fold is reused rather than recomputed. But a warm pass still reported ~3.3 s in the steps phase with stepsMotion reused=60/60 beside it, so the fold was provably not the cost and nothing said what was.

The phase is bracketed as one number and sits outside the #1538 day-loop tally, so three candidates were indistinguishable: the sixty per-day probe queries, the one appleDaily read, and the in-memory calibration fit. Batching the probes into a grouped query is the obvious next move, but building it on that reasoning would be guessing.

What it measures

Two probes, chosen because each has exactly one call site on both platforms, so the counts attribute themselves with no bookkeeping at the call site and no way to drift:

  • ownerHr: hasHrInWindow, the day-owner resolver's per-candidate presence probe. Runs in both the scoring loop and the sixty-day steps loop, and is skipped entirely on a default single-strap install (Allow editing sleep start and end date/time #970).
  • gravityFp: gravityFingerprint, the steps loop's per-day motion witness. Steps-only.

One line per pass, beside the existing reused=N/M:

analyzeRecent storeProbes total=3130ms ownerHr=81/1240ms gravityFp=60/1890ms

Read together the two lines are decisive rather than suggestive. A warm pass that folded nothing and still spent its time here means the round trips are the cost and the grouped query is worth building; one that did not means the cost is the appleDaily read or the fit, and batching would have bought nothing.

Calls print beside the milliseconds because they answer different questions. The time says whether this is where the pass went; the count says whether the loop issued the number of round trips it was believed to, one per day. A right count with a large time is a slow query, a wrong count is a different bug, and one line should not be able to hide either.

Where the counting lives, and why

One level down, in the store rather than at the call site, for a mechanical reason on each platform:

  • analyzeRecentOnCpu sits 210 bytes under the JaCoCo ratchet and the steps loop is inside it. A stopwatch there costs about 467, and the ratchet's own note says to extract rather than raise it.
  • The Swift resolver is nonisolated static, so it has nowhere to accumulate, and the steps loop runs inside a detached task.

Both platforms reset and emit in the unbudgeted analyzeRecent wrapper, so the budgeted method gains nothing at all and IntelligenceEngineJacocoBudgetTest still passes. Swift keeps the counters on the WhoopStore actor, so no lock and no Sendable gymnastics; Android uses atomics in WhoopRepository.

Scope

Instrumentation only. Nothing reads the counters but the log line, and neither probe changes behaviour. A single-strap install renders ownerHr=0/0ms, which is a finding rather than a gap and is pinned as its own test.

Tests

Both platforms pin the same literals, including the backwards-clock clamp where Swift's round-half-away-from-zero and Kotlin's round-half-up would otherwise disagree at exactly -0.5 ms.

  • Android: :app:testFullDebugUnitTest green with --no-build-cache, 686 classes / 5782 tests / 0 failures, IntelligenceEngineJacocoBudgetTest included
  • Swift: StrandAnalytics does not build under WSL, so the renderer was verified in an isolated swiftc harness against the same four literals the Kotlin test pins

Not verified here

The store-side counting on both platforms needs CI, and the numbers themselves need a device: one warm pass on a two-strap library, read alongside stepsMotion reused=60/60, settles whether the grouped-query change is worth building.

With the steps-calibration fold reused rather than recomputed, a warm pass
still reported ~3.3 s in the steps phase with stepsMotion reused=60/60 beside
it. The fold was provably not the cost and nothing said what was: the phase is
bracketed as one number and sits outside the #1538 day-loop tally, so the
sixty per-day probe queries, the one appleDaily read and the in-memory
calibration fit were indistinguishable from each other.

Count and time the two probes that have exactly ONE call site each, so the
numbers attribute themselves with no bookkeeping at the call site and no way to
drift: hasHrInWindow, the day-owner resolver's per-candidate presence probe,
and gravityFingerprint, the steps loop's per-day motion witness. Emitted as one
line beside the existing reused=N/M line, which together answer the question a
batching change would otherwise be built on a guess: a warm pass that folded
nothing and still spent its time here means the round trips are the cost, and
one that did not means they are not.

Calls are printed beside the milliseconds because they answer different
questions. The time says whether this is where the pass went; the count says
whether the loop issued the number of round trips it was believed to, one per
day. A right count with a large time is a slow query, a wrong count is a
different bug, and one line should not be able to hide either.

Counted one level down, in the store rather than at the call site, for a
mechanical reason on each platform. analyzeRecentOnCpu sits 210 bytes under the
JaCoCo ratchet and the steps loop is inside it, so a stopwatch there costs more
than the margin and the ratchet's own note says to extract rather than raise;
the Swift resolver is nonisolated static and has nowhere to accumulate. Both
platforms reset and emit in the unbudgeted wrapper, so the budgeted method is
untouched and its test still passes.

Both sides count MONOTONIC nanoseconds and accumulate them as integers, dividing
once when the line is rendered. A Date() difference would have been wrong in the
one direction the clamp does not cover, since a forward clock correction
mid-probe adds itself to that probe's time and inflates the total the decision
reads. Summing per-call Double seconds would have been wrong differently: sixty
calls of 20 ms accumulate to 1.2000000000000006 rather than 1.2, against a twin
that spends no roundings at all, and the difference reaches the rendered
millisecond whenever the true total sits near a half-millisecond boundary.

Instrumentation only. Nothing reads the counters but the log line, and a
single-strap install renders ownerHr=0/0ms because #970 skips that probe
entirely, which is a finding rather than a gap.
@ryanbr
ryanbr force-pushed the diag/store-probe-tally branch from 6f662ca to 3450a04 Compare September 9, 2026 10:01
@ryanbr

ryanbr commented Sep 9, 2026

Copy link
Copy Markdown
Owner Author

Two re-review passes before merging, both of which found real defects, and both in the measurement itself. Fixed in 3450a04.

1. Swift measured with a wall clock while Kotlin measured with a monotonic one. Swift used Date() differences; Kotlin uses System.nanoTime(). The render-side clamp covers a backwards step, but nothing covered a forward one: an NTP correction landing mid-probe adds itself to that probe's time and inflates the very total the batching decision would read. Swift now counts DispatchTime.now().uptimeNanoseconds, so both sides measure the same thing, and both exclude device sleep.

2. The two platforms did different arithmetic on the way to the same line. Kotlin sums integer nanos into an AtomicLong and divides once at render. Swift divided each call to Double seconds and accumulated those, spending sixty to eighty roundings against a twin that spends none. Sixty calls of exactly 20 ms accumulate to 1.2000000000000006 rather than 1.2, verified rather than argued, and that difference reaches the rendered millisecond whenever the true total sits near a half-millisecond boundary. That is the exact boundary the clamp test already pins, in a file whose whole purpose is one comparable line across two platforms. Swift now accumulates integer nanos and divides once.

Both are pinned rather than left to reasoning: a new StoreProbeCountsTests on the Swift side and two new cases on the Kotlin side assert the same literal, gravityFp=60/1200ms from sixty 20 ms calls, plus that the drain actually drains so a pass cannot inherit its predecessor's work.

The clamp test's justification was also corrected. It used to claim the probes' clock could step backwards; with monotonic counting on both sides it cannot, so the test now says what it actually guarantees, which is a property of the renderer for any caller rather than a repair of these inputs.

Also checked and clear: syncRead is fully synchronous, so there is no suspension point between the timestamp and the defer and no interleaving within a probe. Swift does serialise passes after all, via guard !computing and the computing = true set, so overlapping passes cannot muddle attribution, and the reset sits inside that guarded region ahead of both probe call sites. A throwing probe is still counted, which is correct because it still consumed the time.

Android green with --no-build-cache: 686 classes / 5784 tests / 0 failures, JaCoCo budget included. Swift verified in the isolated harness against the same literals.

@ryanbr
ryanbr merged commit 818f24a into main Sep 9, 2026
16 checks passed
@ryanbr
ryanbr deleted the diag/store-probe-tally branch September 9, 2026 10:14
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.

1 participant