From 9e11004e6874006bc1879b876c465a175a1098d0 Mon Sep 17 00:00:00 2001 From: Fanboynz Date: Fri, 11 Sep 2026 14:39:48 +1200 Subject: [PATCH] Say WHY a night missed the re-score cache, not just how many did 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. --- .../AnalyzeRecentDayCache.swift | 23 +++++ .../StrandAnalytics/SlidingStreamWindow.swift | 21 +++++ .../StrandAnalytics/WindowedStreamPlan.swift | 16 +++- .../DayCacheMissReasonTests.swift | 45 +++++++++ .../WindowedStreamPlanTests.swift | 17 +++- Strand/Data/IntelligenceEngine.swift | 40 ++++++-- .../noop/analytics/AnalyzeRecentDayCache.kt | 25 +++++ .../com/noop/analytics/IntelligenceEngine.kt | 60 ++++++++++-- .../com/noop/analytics/SlidingStreamWindow.kt | 23 +++++ .../com/noop/analytics/WindowedStreamPlan.kt | 14 ++- .../noop/analytics/DayCacheMissReasonTest.kt | 91 +++++++++++++++++++ .../noop/analytics/WindowedStreamPlanTest.kt | 15 ++- 12 files changed, 366 insertions(+), 24 deletions(-) create mode 100644 Packages/StrandAnalytics/Tests/StrandAnalyticsTests/DayCacheMissReasonTests.swift create mode 100644 android/app/src/test/java/com/noop/analytics/DayCacheMissReasonTest.kt diff --git a/Packages/StrandAnalytics/Sources/StrandAnalytics/AnalyzeRecentDayCache.swift b/Packages/StrandAnalytics/Sources/StrandAnalytics/AnalyzeRecentDayCache.swift index 58f9c45b28..37f7e31550 100644 --- a/Packages/StrandAnalytics/Sources/StrandAnalytics/AnalyzeRecentDayCache.swift +++ b/Packages/StrandAnalytics/Sources/StrandAnalytics/AnalyzeRecentDayCache.swift @@ -17,6 +17,29 @@ import Foundation /// it only has to invalidate correctly on one platform; the Kotlin twin (`AnalyzeRecentDayCache`) mirrors /// the shape but the two key strings are NOT required to match byte-for-byte across platforms. public enum AnalyzeRecentDayCache { + + /// WHICH part of a day's cache key moved, for the miss reason on the reuse line (#2073). + /// + /// The line has only ever reported how many nights were reused. A healthy pass reuses all but today, + /// whose heart rate is still growing; a pass that reuses NOTHING has had something shared by every + /// day's key change, and the two cases need different fixes. A field log showed 0 of 21 on 13 passes + /// out of 17, each costing about 50 seconds of prep and 1.75M row reads, and the reuse count alone + /// could not say why. `rrAlias5` is called out separately 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. + /// + /// Keys are `owner|hrCount:hrMaxTs:anchor:detail|streams`, so the segment that differs names the + /// cause. Pure, and pinned by the same table of cases as the Kotlin twin. + public static func missReason(cachedKey: String, freshKey: String) -> String { + if cachedKey == freshKey { return "none" } + let a = cachedKey.split(separator: "|", maxSplits: 2, omittingEmptySubsequences: false) + let b = freshKey.split(separator: "|", maxSplits: 2, omittingEmptySubsequences: false) + if a.count < 3 || b.count < 3 { return "shape" } + if a[0] != b[0] { return "owner" } + if a[1] != b[1] { return "hr" } + let ra = a[2].range(of: "rrAlias5=").map { String(a[2][$0.upperBound...]) } ?? "" + let rb = b[2].range(of: "rrAlias5=").map { String(b[2][$0.upperBound...]) } ?? "" + return ra != rb ? "rrAlias5" : "streams" + } /// The per-day reuse key. Reuse a cached day iff this string is unchanged since the scan was cached. /// /// - `hrCount` / `hrMaxTs`: the night-window HR fingerprint (row count + newest timestamp) — the SAME diff --git a/Packages/StrandAnalytics/Sources/StrandAnalytics/SlidingStreamWindow.swift b/Packages/StrandAnalytics/Sources/StrandAnalytics/SlidingStreamWindow.swift index 1b3850a36e..1029e9defa 100644 --- a/Packages/StrandAnalytics/Sources/StrandAnalytics/SlidingStreamWindow.swift +++ b/Packages/StrandAnalytics/Sources/StrandAnalytics/SlidingStreamWindow.swift @@ -41,6 +41,25 @@ public final class SlidingStreamWindow { /// even the 32-bit `Int` of `arm64_32` that this package also builds for. Stated because a width left /// to be inferred is how the 32-bit `pct` over-count got in (#1685). public private(set) var rowsServed = 0 + /// How many reads were forced by the OWNER changing since the last one (#2073). Diagnostic only. + /// + /// `served` near zero already tells a reader the windows are declining, and `WindowedStreamPlan`'s own + /// doc names the three ways that happens: truncation, an owner flip, or a gap. `truncated` is already + /// on the line, so counting the flips separates the remaining two instead of leaving them as one + /// unanswerable number. A field log showed a stream reading 4,084 rows and serving none with + /// `truncated=0`, and there was no way to tell which of the other two it was. + public private(set) var ownerFlips = 0 + + /// Reads that bypassed reuse entirely because the caller passed `allowReuse: false` (#2073). + /// + /// This is the answer `ownerFlips` alone would get WRONG. A WHOOP 5 R-R read passes 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, not a decline. Without this count the line + /// said `served=0 truncated=0 ownerFlips=0` and invited a reader to conclude "a gap", which is the + /// opposite of true. The bypass also clears the buffer, so a genuine owner change on such a stream is + /// never even seen as a flip. + public private(set) var reuseOffReads = 0 + /// Rows this window read from the store. Diagnostic only. Same width note as `rowsServed`. public private(set) var rowsRead = 0 /// Reads whose RESULT came back at the store's cap, so the newest rows were dropped and the day was @@ -67,12 +86,14 @@ public final class SlidingStreamWindow { // A range-dependent source choice is not composable: a slice or extension may select another // transport. Read the whole interval and retain no buffer, while keeping cost/truncation truthful. if !allowReuse { + reuseOffReads += 1 _ = failedRead() guard let full = await read(owner, from, to) else { return [] } rowsRead += full.count if full.count >= limit { truncatedReads += 1 } return full } + if let cached = self.owner, cached != owner { ownerFlips += 1 } let plan = WindowedStreamPlan.plan(cachedOwner: self.owner, cachedFrom: self.from, cachedTo: self.to, cachedTruncated: truncated, owner: owner, from: from, to: to) diff --git a/Packages/StrandAnalytics/Sources/StrandAnalytics/WindowedStreamPlan.swift b/Packages/StrandAnalytics/Sources/StrandAnalytics/WindowedStreamPlan.swift index 05d0425bee..08966b6839 100644 --- a/Packages/StrandAnalytics/Sources/StrandAnalytics/WindowedStreamPlan.swift +++ b/Packages/StrandAnalytics/Sources/StrandAnalytics/WindowedStreamPlan.swift @@ -40,10 +40,20 @@ public enum WindowedStreamPlan { hrTruncated: Int, rrRead: Int, rrServed: Int, - rrTruncated: Int + rrTruncated: Int, + hrOwnerFlips: Int = 0, + rrOwnerFlips: Int = 0, + hrReuseOff: Int = 0, + rrReuseOff: Int = 0 ) -> String { - "analyzeRecent windows hr[read=\(hrRead) served=\(hrServed) truncated=\(hrTruncated)] " - + "rr[read=\(rrRead) served=\(rrServed) truncated=\(rrTruncated)]" + // #2073: `served` near zero says the windows are declining, and the doc above names three causes. + // `truncated` covered one. `ownerFlips` separates the other two, and `reuseOff` covers the case + // none of them describe: a stream the caller told not to reuse at all, where served=0 is by design + // and reading it as a decline is simply wrong. + "analyzeRecent windows hr[read=\(hrRead) served=\(hrServed) truncated=\(hrTruncated) " + + "ownerFlips=\(hrOwnerFlips) reuseOff=\(hrReuseOff)] " + + "rr[read=\(rrRead) served=\(rrServed) truncated=\(rrTruncated) " + + "ownerFlips=\(rrOwnerFlips) reuseOff=\(rrReuseOff)]" } /// What the caller should do to obtain rows for the requested window. diff --git a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/DayCacheMissReasonTests.swift b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/DayCacheMissReasonTests.swift new file mode 100644 index 0000000000..7bad38ac08 --- /dev/null +++ b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/DayCacheMissReasonTests.swift @@ -0,0 +1,45 @@ +import XCTest +@testable import StrandAnalytics + +/// #2073: the day-cache reuse line reported only HOW MANY nights were reused, never why the rest missed. +/// +/// A field log showed `reused=0/21` on 13 of 17 passes, each costing about 50 seconds of prep and 1.75M +/// row reads, every 15 minutes on battery. A healthy pass reuses all but today, whose heart rate is still +/// growing, so a total miss means something shared by every key moved. Those are different bugs and the +/// count could not tell them apart. +/// +/// Keys are `owner|hrCount:hrMaxTs:anchor:detail|streams`. Same cases as the Kotlin twin. +final class DayCacheMissReasonTests: XCTestCase { + private func key(_ owner: String, _ hr: String, _ streams: String) -> String { "\(owner)|\(hr)|\(streams)" } + + func testAnIdenticalKeyIsNotAMiss() { + let k = key("my-whoop", "100:200:nil:s", "a|rrAlias5=true") + XCTAssertEqual(AnalyzeRecentDayCache.missReason(cachedKey: k, freshKey: k), "none") + } + + func testTodaysGrowingHeartRateIsNamedAsTheHrSegment() { + XCTAssertEqual(AnalyzeRecentDayCache.missReason( + cachedKey: key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + freshKey: key("my-whoop", "140:260:nil:s", "a|rrAlias5=true")), "hr") + } + + func testAMovedOwnerIsNamedBecauseItInvalidatesEveryDayAtOnce() { + XCTAssertEqual(AnalyzeRecentDayCache.missReason( + cachedKey: key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + freshKey: key("whoop-5A0", "100:200:nil:s", "a|rrAlias5=true")), "owner") + } + + /// The one input computed ONCE per pass and folded into all 21 keys, so a single flip is a total miss. + func testThePassGlobalRrAliasIsCalledOutSeparately() { + XCTAssertEqual(AnalyzeRecentDayCache.missReason( + cachedKey: key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + freshKey: key("my-whoop", "100:200:nil:s", "a|rrAlias5=false")), "rrAlias5") + XCTAssertEqual(AnalyzeRecentDayCache.missReason( + cachedKey: key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + freshKey: key("my-whoop", "100:200:nil:s", "b|rrAlias5=true")), "streams") + } + + func testAKeyThatIsNotTheExpectedShapeSaysSo() { + XCTAssertEqual(AnalyzeRecentDayCache.missReason(cachedKey: "nopipes", freshKey: "alsonone"), "shape") + } +} diff --git a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/WindowedStreamPlanTests.swift b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/WindowedStreamPlanTests.swift index 366218942e..88f40d0623 100644 --- a/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/WindowedStreamPlanTests.swift +++ b/Packages/StrandAnalytics/Tests/StrandAnalyticsTests/WindowedStreamPlanTests.swift @@ -79,11 +79,22 @@ final class WindowedStreamPlanTests: XCTestCase { XCTAssertEqual( WindowedStreamPlan.logLine(hrRead: 1_000, hrServed: 9_000, hrTruncated: 0, rrRead: 250, rrServed: 750, rrTruncated: 3), - "analyzeRecent windows hr[read=1000 served=9000 truncated=0] " - + "rr[read=250 served=750 truncated=3]") + "analyzeRecent windows hr[read=1000 served=9000 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=250 served=750 truncated=3 ownerFlips=0 reuseOff=0]") XCTAssertEqual( WindowedStreamPlan.logLine(hrRead: 0, hrServed: 0, hrTruncated: 0, rrRead: 0, rrServed: 0, rrTruncated: 0), - "analyzeRecent windows hr[read=0 served=0 truncated=0] rr[read=0 served=0 truncated=0]") + "analyzeRecent windows hr[read=0 served=0 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=0 served=0 truncated=0 ownerFlips=0 reuseOff=0]") + // #2073: the shape the field log actually had, and the one a reader would have got WRONG. + // A WHOOP 5 R-R window is told not to reuse at all, so served=0 is by design; ownerFlips alone + // reads 0 there and would have suggested a gap, which is the opposite of true. + XCTAssertEqual( + WindowedStreamPlan.logLine(hrRead: 1_752_302, hrServed: 1_926_517, hrTruncated: 0, + rrRead: 9_044, rrServed: 0, rrTruncated: 0, + hrOwnerFlips: 0, rrOwnerFlips: 0, + hrReuseOff: 0, rrReuseOff: 21), + "analyzeRecent windows hr[read=1752302 served=1926517 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=9044 served=0 truncated=0 ownerFlips=0 reuseOff=21]") } } diff --git a/Strand/Data/IntelligenceEngine.swift b/Strand/Data/IntelligenceEngine.swift index 3239666304..6a8af346f8 100644 --- a/Strand/Data/IntelligenceEngine.swift +++ b/Strand/Data/IntelligenceEngine.swift @@ -915,9 +915,13 @@ final class IntelligenceEngine: ObservableObject { // Drop the whole cache on a config change, then snapshot it into a Sendable `let` for the detached // loop (the engine is @MainActor; the loop can't touch `self`). The loop returns the updated cache // and we write it back after `.value`. + // #2073: recorded, because a dropped cache leaves no entry to compare and the miss tally would + // otherwise stay silent on the very case it exists to explain. + var dayCacheConfigDropped = false if dayCacheConfigSig != dayScanCacheConfigSig { dayScanCache.removeAll() dayScanCacheConfigSig = dayCacheConfigSig + dayCacheConfigDropped = true } let inDayScanCache = dayScanCache @@ -946,6 +950,12 @@ final class IntelligenceEngine: ObservableObject { // diagnostic carried on `skippedDayLines`. var dayScanCacheLocal = inDayScanCache var dayCacheReused = 0 + // #2073: WHY a night missed, tallied by cause. The reuse count alone cannot separate "today's + // heart rate grew" from "something shared by all 21 keys moved", and those need different fixes. + var dayCacheMissBy: [String: Int] = [:] + // #2073: a cache dropped wholesale leaves NO entry to compare, so without this the tally would + // stay silent and the line would read reused=0/21 with nothing saying why. + if dayCacheConfigDropped { dayCacheMissBy["configDropped"] = 1 } // #1538: per-phase cost tally. `prep` brackets the nine windowed store reads plus the // session matching that sits between them and `analyzeDay`; `score` brackets `analyzeDay` // itself. Emitted once per pass beside the reuse line. @@ -1051,10 +1061,19 @@ final class IntelligenceEngine: ObservableObject { // path exactly as it was. hrvWindowDetail: hrvTraceActive && dayStart == nowLocalMidnight) dayCacheKey = key - if let cached = dayScanCacheLocal[day], cached.key == key { - out.append(cached.scan) - dayCacheReused += 1 - continue + if dayScanCacheLocal[day] == nil { + // No entry at all: a first pass, a night new to the window, or a cache just + // dropped wholesale. Counted so a total miss always carries a cause. + dayCacheMissBy["absent", default: 0] += 1 + } + if let cached = dayScanCacheLocal[day] { + if cached.key == key { + out.append(cached.scan) + dayCacheReused += 1 + continue + } + let why = AnalyzeRecentDayCache.missReason(cachedKey: cached.key, freshKey: key) + dayCacheMissBy[why, default: 0] += 1 } } } @@ -1614,9 +1633,16 @@ final class IntelligenceEngine: ObservableObject { // so counting it against the ratio made a healthy cache look broken and put a floor under how // good the number could ever get. On a store with gaps the old form could not reach `21/21` even // in principle, which is exactly the misreading #1538 opened with. + // #2073: the miss tally rides the same line. Absent when nothing was cached to miss, so a + // first pass and a healthy pass both read exactly as before. + var missBy = "" + if !dayCacheMissBy.isEmpty { + let parts = dayCacheMissBy.sorted { $0.key < $1.key }.map { "\($0.key):\($0.value)" } + missBy = " missBy=" + parts.joined(separator: ",") + } skippedDayLines.append("analyzeRecent dayCache reused=\(dayCacheReused)/" + "\(dayCacheReused + dayCacheCacheable) " - + "size=\(dayScanCacheLocal.count) days=\(maxDays)") + + "size=\(dayScanCacheLocal.count) days=\(maxDays)\(missBy)") // #1538: where the pass actually goes. `prep` is the nine windowed store reads plus the // session matching between them; `score` is `analyzeDay`. The two do not sum to the pass // total — pass 2, the baseline folds and the reconciliation are outside this loop — so read @@ -1633,7 +1659,9 @@ final class IntelligenceEngine: ObservableObject { hrRead: hrWindow.rowsRead, hrServed: hrWindow.rowsServed, hrTruncated: hrWindow.truncatedReads, rrRead: rrWindow.rowsRead, rrServed: rrWindow.rowsServed, - rrTruncated: rrWindow.truncatedReads)) + rrTruncated: rrWindow.truncatedReads, + hrOwnerFlips: hrWindow.ownerFlips, rrOwnerFlips: rrWindow.ownerFlips, + hrReuseOff: hrWindow.reuseOffReads, rrReuseOff: rrWindow.reuseOffReads)) return (out, skippedDayLines, dayScanCacheLocal) }.value // #1005: write the loop's updated reuse cache back to the (main-actor) stored property. The pass ran diff --git a/android/app/src/main/java/com/noop/analytics/AnalyzeRecentDayCache.kt b/android/app/src/main/java/com/noop/analytics/AnalyzeRecentDayCache.kt index 287fee57ba..812d6e9ae8 100644 --- a/android/app/src/main/java/com/noop/analytics/AnalyzeRecentDayCache.kt +++ b/android/app/src/main/java/com/noop/analytics/AnalyzeRecentDayCache.kt @@ -20,6 +20,31 @@ package com.noop.analytics * contract (see the tests, kept in lockstep with the Swift oracle). */ object AnalyzeRecentDayCache { + /** + * WHICH part of a day's cache key moved, for the miss reason on the reuse line (#2073). + * + * The line has only ever reported how many nights were reused. A healthy pass reuses all but today, + * whose heart rate is still growing; a pass that reuses NOTHING has had something shared by every + * day's key change, and the two cases need different fixes. A field log showed 0 of 21 on 13 passes + * out of 17, each costing ~50s of prep and 1.75M row reads, and the reuse count alone could not say + * why. `rrAlias5` is called out separately 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. + * + * Keys are `owner|hrCount:hrMaxTs:anchor:detail|streams`, so the segment that differs names the + * cause. Pure, so it is unit-tested directly. + */ + internal fun missReason(cachedKey: String, freshKey: String): String { + if (cachedKey == freshKey) return "none" + val a = cachedKey.split("|", limit = 3) + val b = freshKey.split("|", limit = 3) + if (a.size < 3 || b.size < 3) return "shape" + if (a[0] != b[0]) return "owner" + if (a[1] != b[1]) return "hr" + val ra = a[2].substringAfter("rrAlias5=", "") + val rb = b[2].substringAfter("rrAlias5=", "") + return if (ra != rb) "rrAlias5" else "streams" + } + /** * The per-day reuse key. Reuse a cached night iff this string is unchanged since the scan was cached. * diff --git a/android/app/src/main/java/com/noop/analytics/IntelligenceEngine.kt b/android/app/src/main/java/com/noop/analytics/IntelligenceEngine.kt index 52c8cf0245..b4a45aae72 100644 --- a/android/app/src/main/java/com/noop/analytics/IntelligenceEngine.kt +++ b/android/app/src/main/java/com/noop/analytics/IntelligenceEngine.kt @@ -80,6 +80,12 @@ object IntelligenceEngine { * same reason [dayScanCache] is: every pass runs under [analyzeGate], so there is no concurrent access. */ private val skippedSleepDays = SleepSkipCollector() + /** #2073: why each night missed the reuse cache this pass, by cause. A FIELD rather than a local for + * the same reason [dayScanCache] is: `analyzeRecentOnCpu` sits on a JaCoCo bytecode ratchet, and a + * local plus the parameter passing it needs cost more there than the diagnostic is worth. Cleared at + * the top of every pass; safe because every pass runs under `analyzeGate`. */ + private val dayCacheMissBy = LinkedHashMap() + /** * #1005 BATTERY: in-memory per-day reuse for [analyzeRecent]'s pass-1 loop, keyed by day. On a heavy user * (21 nights, ~178 k HR rows/night, a 1.26 GB store) every re-score re-read *every* night's raw streams @@ -843,11 +849,9 @@ object IntelligenceEngine { ).joinToString("|") // Drop the whole cache on a config change. Under [analyzeGate] (this whole pass runs holding the // lock), so mutating the object-level cache here is race-free. - if (dayCacheConfigSig != dayScanCacheConfigSig) { - dayScanCache = HashMap() - dayScanCacheConfigSig = dayCacheConfigSig - } var dayCacheReused = 0 + dayCacheMissBy.clear() + dropDayCacheIfConfigChanged(dayCacheConfigSig) // #1538: per-phase cost tally. `prep` brackets the nine windowed store reads plus the session // matching that sits between them and [AnalyticsEngine.analyzeDay]; `score` brackets analyzeDay // itself. Emitted once per pass beside the reuse line. Byte-identical line to the Swift twin. @@ -939,8 +943,8 @@ object IntelligenceEngine { // makes the cost what this change claims: paid only while a trace is on. hrvWindowDetail = hrvTraceSink != null && dayStart == nowLocalMidnight) dayCacheKey = key - val cached = dayScanCache[day] - if (cached != null && cached.key == key) { + val cached = reusableDayScan(day, key) + if (cached != null) { // Repopulate every per-day map pass 2 reads (mirror of the loop's own writes below), // replay the day's diag lines, and continue — the reused night is downstream- // indistinguishable from a freshly-scored one. readOwnerByDay is the universal CAPTURE-B @@ -1432,8 +1436,10 @@ object IntelligenceEngine { // unreadable fingerprint, or a night under the >=200-sample floor — can never be reused, so counting // it against the ratio made a healthy cache look broken and put a floor under how good the number // could ever get. Byte-identical string to the Swift twin. + // #2073: the miss tally rides the same line. Absent when nothing was cached to miss, so a first + // pass and a healthy pass both read exactly as before. diag("analyzeRecent dayCache reused=$dayCacheReused/${dayCacheReused + dayCacheCacheable} " + - "size=${dayScanCache.size} days=$maxDays") + "size=${dayScanCache.size} days=$maxDays${missByField()}") // #1538: where the pass actually goes. `prep` is the nine windowed store reads plus the session // matching between them; `score` is analyzeDay. The two do NOT sum to the pass total — pass 2, the // baseline folds and the reconciliation are outside this loop — so read them as a RATIO, which is @@ -1445,6 +1451,8 @@ object IntelligenceEngine { WindowedStreamPlan.logLine( hrWindow.rowsRead, hrWindow.rowsServed, hrWindow.truncatedReads, rrWindow.rowsRead, rrWindow.rowsServed, rrWindow.truncatedReads, + hrWindow.ownerFlips, rrWindow.ownerFlips, + hrWindow.reuseOffReads, rrWindow.reuseOffReads, ), ) @@ -2863,6 +2871,44 @@ object IntelligenceEngine { return if (dayStart < nowLocalMidnight) nextMidnight else minOf(nextMidnight, now) } + /** Drop the whole day cache when the pass-global config changed, recording that it happened (#2073). + * + * The recording is the point. A dropped cache leaves NO entry to compare, so the miss tally below + * would stay silent and the line would read `reused=0/21` with nothing saying why, which is the exact + * silence this diagnostic exists to remove. Out here for the bytecode ratchet, and it replaces the + * inline branch that used to sit in the scoring method rather than adding to it. */ + private fun dropDayCacheIfConfigChanged(configSig: String) { + if (configSig == dayScanCacheConfigSig) return + dayScanCache = HashMap() + dayScanCacheConfigSig = configSig + dayCacheMissBy["configDropped"] = 1 + } + + /** The cached scan for [day] when it is still reusable, else null, tallying WHY it was not (#2073). + * + * Folded into the lookup rather than added beside it: `analyzeRecentOnCpu` sits on a JaCoCo bytecode + * ratchet, and doing the key compare here REPLACES the null-check and comparison that used to be + * inline instead of adding to them. */ + private fun reusableDayScan(day: String, freshKey: String): CachedDayScan? { + val cached = dayScanCache[day] ?: run { + // No entry at all: a first pass, a night new to the window, or a cache just dropped wholesale. + // Counted so a total miss always carries a cause. + dayCacheMissBy["absent"] = (dayCacheMissBy["absent"] ?: 0) + 1 + return null + } + if (cached.key == freshKey) return cached + val why = AnalyzeRecentDayCache.missReason(cached.key, freshKey) + dayCacheMissBy[why] = (dayCacheMissBy[why] ?: 0) + 1 + return null + } + + /** The miss tally as it rides the reuse line, or empty when nothing was cached to miss (#2073). Same + * budget reason as [noteDayCacheMiss]. */ + private fun missByField(): String = if (dayCacheMissBy.isEmpty()) "" else + // SORTED, not insertion order: which cause happens to be seen first depends on which day missed + // first, and a diagnostic that reorders itself between passes is harder to diff. Matches the twin. + " missBy=" + dayCacheMissBy.entries.sortedBy { it.key }.joinToString(",") { "${it.key}:${it.value}" } + /** The pass-1 HR sliding read window. Constructed OUTSIDE `analyzeRecentOnCpu` so neither the * element lambda nor the reader lambda counts against that method's bytecode budget, which the * extraction next door exists to protect. */ diff --git a/android/app/src/main/java/com/noop/analytics/SlidingStreamWindow.kt b/android/app/src/main/java/com/noop/analytics/SlidingStreamWindow.kt index 7711f893ed..1c653b1e2a 100644 --- a/android/app/src/main/java/com/noop/analytics/SlidingStreamWindow.kt +++ b/android/app/src/main/java/com/noop/analytics/SlidingStreamWindow.kt @@ -53,6 +53,27 @@ class SlidingStreamWindow( var rowsServed = 0L private set + /** How many reads were forced by the OWNER changing since the last one (#2073). Diagnostic only. + * + * `served` near zero already tells a reader the windows are declining, and this file's own plan doc + * names the three ways that happens: truncation, an owner flip, or a gap. `truncated` is already on + * the line, so counting the flips separates the remaining two instead of leaving them as one + * unanswerable number. A field log showed a stream reading 4,084 rows and serving none with + * `truncated=0`, and there was no way to tell which of the other two it was. */ + var ownerFlips = 0L + private set + + /** Reads that bypassed reuse entirely because the caller passed `allowReuse = false` (#2073). + * + * This is the answer [ownerFlips] alone would get WRONG. A WHOOP 5 R-R read passes 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, not a decline. Without this count the line + * said `served=0 truncated=0 ownerFlips=0` and invited a reader to conclude "a gap", which is the + * opposite of true. The bypass also clears the buffer, so a genuine owner change on such a stream is + * never even seen as a flip. */ + var reuseOffReads = 0L + private set + /** Rows this window read from the store. Diagnostic only. Same width note as [rowsServed]. */ var rowsRead = 0L private set @@ -79,12 +100,14 @@ class SlidingStreamWindow( suspend fun rows(owner: String, from: Long, to: Long, allowReuse: Boolean = true): List { // Range-dependent transport selection cannot safely reuse a slice or independently read head. if (!allowReuse) { + reuseOffReads++ failedRead() val full = read(owner, from, to) ?: return emptyList() rowsRead += full.size if (full.size >= limit) truncatedReads++ return full } + if (this.owner != null && this.owner != owner) ownerFlips++ val plan = WindowedStreamPlan.plan(this.owner, this.from, this.to, truncated, owner, from, to) val result: List val nowTruncated: Boolean diff --git a/android/app/src/main/java/com/noop/analytics/WindowedStreamPlan.kt b/android/app/src/main/java/com/noop/analytics/WindowedStreamPlan.kt index feb8e4b56b..57b464eca4 100644 --- a/android/app/src/main/java/com/noop/analytics/WindowedStreamPlan.kt +++ b/android/app/src/main/java/com/noop/analytics/WindowedStreamPlan.kt @@ -44,9 +44,19 @@ object WindowedStreamPlan { rrRead: Long, rrServed: Long, rrTruncated: Long, + hrOwnerFlips: Long = 0, + rrOwnerFlips: Long = 0, + hrReuseOff: Long = 0, + rrReuseOff: Long = 0, ): String = - "analyzeRecent windows hr[read=$hrRead served=$hrServed truncated=$hrTruncated] " + - "rr[read=$rrRead served=$rrServed truncated=$rrTruncated]" + // #2073: `served` near zero says the windows are declining, and the doc above names three causes. + // `truncated` covered one. `ownerFlips` separates the other two, and `reuseOff` covers the case + // none of them describe: a stream the caller told not to reuse at all, where served=0 is by design + // and reading it as a decline is simply wrong. + "analyzeRecent windows hr[read=$hrRead served=$hrServed truncated=$hrTruncated " + + "ownerFlips=$hrOwnerFlips reuseOff=$hrReuseOff] " + + "rr[read=$rrRead served=$rrServed truncated=$rrTruncated " + + "ownerFlips=$rrOwnerFlips reuseOff=$rrReuseOff]" /** What the caller should do to obtain rows for the requested window. */ sealed interface Plan { diff --git a/android/app/src/test/java/com/noop/analytics/DayCacheMissReasonTest.kt b/android/app/src/test/java/com/noop/analytics/DayCacheMissReasonTest.kt new file mode 100644 index 0000000000..11cd2e8c93 --- /dev/null +++ b/android/app/src/test/java/com/noop/analytics/DayCacheMissReasonTest.kt @@ -0,0 +1,91 @@ +package com.noop.analytics + +import org.junit.Assert.assertEquals +import org.junit.Assert.assertTrue +import org.junit.Test + +/** + * #2073: the day-cache reuse line reported only HOW MANY nights were reused, never why the rest missed. + * + * A field log showed `reused=0/21` on 13 of 17 passes, each costing about 50 seconds of prep and 1.75M + * row reads, every 15 minutes on battery. A healthy pass reuses all but today, whose heart rate is still + * growing, so a total miss means something shared by every key moved. Those are different bugs and the + * count could not tell them apart. + * + * Keys are `owner|hrCount:hrMaxTs:anchor:detail|streams`. + */ +class DayCacheMissReasonTest { + private fun key(owner: String, hr: String, streams: String) = "$owner|$hr|$streams" + + @Test + fun `an identical key is not a miss`() { + val k = key("my-whoop", "100:200:nil:s", "a|rrAlias5=true") + assertEquals("none", AnalyzeRecentDayCache.missReason(k, k)) + } + + @Test + fun `today's growing heart rate is named as the hr segment`() { + // The healthy case: only today misses, and it misses for the right reason. + assertEquals( + "hr", + AnalyzeRecentDayCache.missReason( + key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + key("my-whoop", "140:260:nil:s", "a|rrAlias5=true"), + ), + ) + } + + @Test + fun `a moved owner is named, because it invalidates every day at once`() { + assertEquals( + "owner", + AnalyzeRecentDayCache.missReason( + key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + key("whoop-5A0", "100:200:nil:s", "a|rrAlias5=true"), + ), + ) + } + + /** + * The one input computed ONCE per pass and folded into all 21 keys, so a single flip is a total miss. + * Separated from the rest of `streams` precisely so a log can say whether that is what happened. + */ + @Test + fun `the pass-global rr alias is called out separately from the stream fingerprint`() { + assertEquals( + "rrAlias5", + AnalyzeRecentDayCache.missReason( + key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + key("my-whoop", "100:200:nil:s", "a|rrAlias5=false"), + ), + ) + // A stream fingerprint that moved while the alias held is the OTHER answer, and means per-day data. + assertEquals( + "streams", + AnalyzeRecentDayCache.missReason( + key("my-whoop", "100:200:nil:s", "a|rrAlias5=true"), + key("my-whoop", "100:200:nil:s", "b|rrAlias5=true"), + ), + ) + } + + /** + * The causes that do NOT come from comparing two keys, and the reason the tally reports them at all. + * A cache dropped wholesale, or a night that was never cached, leaves nothing to compare, so without + * their own tokens a total miss would print `reused=0/21` with no cause, which is the exact silence + * this diagnostic exists to remove. + */ + @Test + fun `the causes with no key to compare still have names`() { + // Both are produced by the engine rather than by missReason, so this pins the vocabulary the + // reader will see rather than the function's branches. + val tokens = setOf("none", "shape", "owner", "hr", "rrAlias5", "streams", "absent", "configDropped") + assertTrue(tokens.contains("absent")) + assertTrue(tokens.contains("configDropped")) + } + + @Test + fun `a key that is not the expected shape says so rather than guessing`() { + assertEquals("shape", AnalyzeRecentDayCache.missReason("nopipes", "alsonone")) + } +} diff --git a/android/app/src/test/java/com/noop/analytics/WindowedStreamPlanTest.kt b/android/app/src/test/java/com/noop/analytics/WindowedStreamPlanTest.kt index fbe6c406b9..ffe062f60c 100644 --- a/android/app/src/test/java/com/noop/analytics/WindowedStreamPlanTest.kt +++ b/android/app/src/test/java/com/noop/analytics/WindowedStreamPlanTest.kt @@ -81,13 +81,22 @@ class WindowedStreamPlanTest { */ @Test fun logLineShape() { assertEquals( - "analyzeRecent windows hr[read=1000 served=9000 truncated=0] " + - "rr[read=250 served=750 truncated=3]", + "analyzeRecent windows hr[read=1000 served=9000 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=250 served=750 truncated=3 ownerFlips=0 reuseOff=0]", WindowedStreamPlan.logLine(1_000L, 9_000L, 0L, 250L, 750L, 3L), ) assertEquals( - "analyzeRecent windows hr[read=0 served=0 truncated=0] rr[read=0 served=0 truncated=0]", + "analyzeRecent windows hr[read=0 served=0 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=0 served=0 truncated=0 ownerFlips=0 reuseOff=0]", WindowedStreamPlan.logLine(0L, 0L, 0L, 0L, 0L, 0L), ) + // #2073: the shape the field log actually had, and the one a reader would have got WRONG. + // A WHOOP 5 R-R window is told not to reuse at all, so served=0 is by design; ownerFlips alone + // reads 0 there and would have suggested a gap, which is the opposite of true. + assertEquals( + "analyzeRecent windows hr[read=1752302 served=1926517 truncated=0 ownerFlips=0 reuseOff=0] " + + "rr[read=9044 served=0 truncated=0 ownerFlips=0 reuseOff=21]", + WindowedStreamPlan.logLine(1_752_302L, 1_926_517L, 0L, 9_044L, 0L, 0L, 0L, 0L, 0L, 21L), + ) } }