Skip to content

Say why a night missed the re-score cache, not just how many did - #2080

Merged
ryanbr merged 1 commit into
mainfrom
diag/daycache-miss-reason
Sep 11, 2026
Merged

ryanbr merged 1 commit into
mainfrom
diag/daycache-miss-reason

Conversation

@ryanbr

@ryanbr ryanbr commented Sep 11, 2026 •

Copy link
Copy Markdown
Owner

From the log on #2073.

The problem the line could not answer

That install re-scores 21 nights every 15 minutes, and the day cache reused nothing on 13 of 17 passes:

analyzeRecent dayCache reused=0/21   ×13
analyzeRecent dayCache reused=20/21  ×4
analyzeRecent stepsMotion reused=58-60/60   <- same passes, different cache

Each total miss costs prep≈50s and hr[read=1752302] , 1.75 million rows, on battery. Passes ran 95 to 195 seconds. The steps cache reusing 58-60 of 60 in those same passes rules out general store slowness: it is this cache's key. For scale, a log from the same reporter on an older build scored the same 21 nights in 16.5 seconds.

The reuse count alone cannot say which bug that is. A healthy pass reuses all but today, whose heart rate is still growing, and 20/21 is exactly that. Reusing nothing means something shared by every day's key moved, which is a different fault with a different fix.

What the line says now

Keys are owner|hrCount:hrMaxTs:anchor:detail|streams, so the segment that differs names the cause:

analyzeRecent dayCache reused=0/21 size=21 days=21 missBy=rrAlias5:21

rrAlias5 gets its own answer because it is the one input computed once per pass and folded into all 21 keys, so a single flip is a total miss. owner likewise moves every day at once. hr is the healthy per-day case. That distinction is the whole point: one more log from the reporter now names the culprit instead of narrowing it.

The same treatment for the windows line, from the same log

analyzeRecent windows hr[read=1752302 served=1926517 truncated=0] rr[read=9044 served=0 truncated=0]

A stream that reads rows and serves none is declining, and WindowedStreamPlan's own doc already names the three ways that happens: truncation, an owner flip, or a gap. truncated was already on the line, so counting owner flips separates the other two instead of leaving them as one unanswerable number:

rr[read=9044 served=0 truncated=0 ownerFlips=20]

But that stream needed a fourth answer the doc does not list, and getting it wrong was easy. A WHOOP 5 R-R read passes allowReuse = false, because transport selection is range-dependent and a slice could mix transports:

allowReuse = !repo.isWhoop5RrSource(owner, unlabelledAliasOfWhoop5)

So that window can never serve from its buffer and served=0 there is by design. ownerFlips alone would have read 0 on exactly that stream, since the bypass returns before the comparison and clears the buffer on the way, and a reader would have concluded "a gap" when the truth is the opposite. The line carries reuseOff too:

rr[read=9044 served=0 truncated=0 ownerFlips=0 reuseOff=21]

Together they say which of the four it is. And where both missBy=owner and a non-zero ownerFlips appear on a stream that IS allowed to reuse, the day owner is moving between passes and that is the whole answer for the cache thrash as well.

Two causes that have no key to compare

The engine drops the WHOLE cache when its pass-global config signature changes, and a night that was never cached has nothing to compare either. Tallying only key differences would have left both silent, so the very case this exists to explain, reusing nothing, could still have printed no cause at all. They report as configDropped and absent.

The bytecode ratchet, which shaped the implementation

analyzeRecentOnCpu sits on a JaCoCo budget and my first two drafts failed it (55,996 and 55,930 against 55,700). Rather than raise the ratchet:

  • the tally is a field, not a local, so neither its declaration nor the parameter passing lands in the method
  • the key compare is folded into the cache lookup (reusableDayScan) instead of added beside it, so it REPLACES the null check and key comparison that used to be inline

Net result 55,605 against the 55,700 budget, smaller than before this change.

Detail

Sorted rather than insertion order: which cause is seen first depends on which day missed first, and a diagnostic that reorders itself between passes is harder to diff. Both platforms produce the same string.

Scope

Diagnostic only. Nothing about what invalidates a night changes, so the cost this exists to explain is untouched and #2073's performance question stays open. I did not want to guess at a cache-key fix when the suspect is an external contributor's correctness change (#2046) and a wrong guess either reintroduces stale scores or hides the real cause.

Verification

Android with --no-build-cache: compileFullDebugKotlin, syncRoomSchemaSnapshot in its own invocation, the full testFullDebugUnitTest including the JaCoCo budget test, doc_comment_lint.py, i18n_audit.py --ci. New Android tests 5 of 5.

The Swift half runs locally, unusually for this repo, because the cache lives in StrandAnalytics rather than the app target: swift test --filter DayCacheMissReasonTests with the docs/BUILD.md snapshot-SQLite flags, 5 of 5 executed.

@ryanbr
ryanbr force-pushed the diag/daycache-miss-reason branch 2 times, most recently from 6fa8fb1 to 2b1af0c Compare September 11, 2026 02:53
From the log on #2073. That install re-scores 21 nights every 15 minutes and the
day cache reused NOTHING on 13 of 17 passes, each one costing about 50 seconds of
prep and 1.75 million heart-rate row reads, on battery. The same passes reused 58
to 60 of 60 in the steps cache, so it is not general store slowness; it is this
cache's key. A pass on an older build scored the same 21 nights in 16.5 seconds.

The count alone cannot say which bug it is. A healthy pass reuses all but today,
whose heart rate is still growing, and reuse=20/21 is exactly that. Reusing
NOTHING means something shared by every day's key moved, which is a different
fault with a different fix, and the line could not tell them apart.

Keys are owner|hrCount:hrMaxTs:anchor:detail|streams, so the segment that differs
names the cause. rrAlias5 is called out on its own because it is the one input
computed ONCE per pass and folded into all 21 keys, so it alone can turn a single
flip into a total miss.

The tally is a FIELD and the key compare is folded into the cache lookup rather
than added beside it. analyzeRecentOnCpu sits on a JaCoCo bytecode ratchet and the
first two drafts of this failed it; doing the compare inside the lookup REPLACES
the null check and comparison that used to be inline, so the instrumented method
comes out at 55,605 against its 55,700 budget, smaller than before this change.

A miss with no key to compare is reported too, and that is the half that matters.
The engine drops the WHOLE cache when its pass-global config signature changes, and
a night that was never cached has nothing to compare either. Tallying only key
differences would have left both silent, so the very case this exists to explain,
reusing nothing, could still have printed no cause at all. They report as
configDropped and absent.

Sorted rather than insertion order: which cause is seen first depends on which day
missed first, and a diagnostic that reorders itself between passes is harder to
diff. Both platforms.

The windows line gains the same treatment, from the same log, and it needed a
fourth answer the plan doc does not list. A stream that reads rows and serves none
is declining, and that doc names three ways: truncation, an owner flip, or a gap.
The reporter's R-R window read 9,044 rows and served none with truncated=0, and
none of the three is the reason. A WHOOP 5 R-R read passes allowReuse = false,
because transport selection is range-dependent and a slice could mix transports, so
that window can NEVER serve from its buffer. served=0 there is by design.

So the line carries both ownerFlips and reuseOff. Flips alone would have read 0 on
exactly that stream, since the bypass returns before the comparison and clears the
buffer on the way, and a reader would have concluded "a gap" when the truth is the
opposite. Together they say which of the four it is.

Diagnostic only. Nothing about what invalidates a night changes, so the cost this
exists to explain is untouched. Twin, with the same table of cases either side,
and the Swift half runs locally because the cache lives in StrandAnalytics rather
than the app target.
@ryanbr
ryanbr force-pushed the diag/daycache-miss-reason branch from 2b1af0c to 9e11004 Compare September 11, 2026 02:57
@ryanbr
ryanbr merged commit 3812131 into main Sep 11, 2026
16 checks passed
@ryanbr
ryanbr deleted the diag/daycache-miss-reason branch September 11, 2026 03:09
@ryanbr ryanbr mentioned this pull request Sep 11, 2026
5 tasks done
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