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), + ) } }