Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
95 changes: 92 additions & 3 deletions Strand/BLE/LiveState.swift
Original file line number Diff line number Diff line change
Expand Up @@ -483,7 +483,26 @@ public final class LiveState: ObservableObject {
return String(watts)
}
/// Rolling log of human-readable lines for the on-device verification checklist.
@Published public var log: [String] = []
///
/// NOT `@Published`, deliberately (#2547). `LiveState` carries dozens of `@Published` properties on one
/// `ObservableObject`, and an `ObservableObject` invalidates EVERY observer on ANY published change, so
/// publishing per appended line woke every view in the app for each line. A history drain plus a
/// re-score burst emits hundreds a minute and iOS killed the app for sustained background CPU (#2521).
///
/// Reads are still SYNCHRONOUS and uncoalesced: this returns the buffer as it is right now, so code that
/// appends and then inspects the log in the same turn sees its own line. Only the PUBLISH is coalesced,
/// via `logRevision`. Capture is never delayed or dropped.
public var log: [String] { logBuffer }

/// The backing store. Mutated only by `append(log:)`.
private var logBuffer: [String] = []

/// Ticks when the log has changed, at most once per `publishCoalesceSeconds` however fast lines arrive.
///
/// This is the property SwiftUI observes for the log. The Android twin is
/// `boundedRevision(ble.logRevision, coalesceMs = 250)` in `TestCentreScreen.kt`, which throttles the
/// same way; this brings the platforms level.
@Published public private(set) var logRevision: UInt64 = 0

// MARK: - Connection status (single source of truth, #266)

Expand Down Expand Up @@ -780,11 +799,15 @@ public final class LiveState: ObservableObject {
// (redactPii below); tagging happens BEFORE redaction so the scrub covers the whole line.
let tagged = domain.map { "[\($0.id)] " + line } ?? line
let safe = Self.redactPii(tagged)
log.append(safe)
logBuffer.append(safe)
// Batched trim: overrun by `trimSlack`, then trim back to the cap in one shot (amortized O(1)/line).
if log.count > Self.maxLogLines + Self.trimSlack { log.removeFirst(log.count - Self.maxLogLines) }
if logBuffer.count > Self.maxLogLines + Self.trimSlack {
logBuffer.removeFirst(logBuffer.count - Self.maxLogLines)
}
// Onto disk as it is logged, so a restart loses nothing and an export carries the runs before it.
// BEFORE the coalesced publish and never inside it: capture is per line, only the notification waits.
Self.archive.append(safe)
publishLogCoalesced()
// #990: fold the Backfiller's per-session "session persisted N rows" summary into the persisted
// ALL-TIME drained-rows tally, right here at the single log sink (no new BLE seam). The summary
// is emitted unconditionally whenever rows landed (#150), so the cumulative counter accrues on
Expand All @@ -795,6 +818,72 @@ public final class LiveState: ObservableObject {
}
}

/// How often at most the log publishes, however fast lines arrive. Matches the Android twin's 250ms.
///
/// `nonisolated` because a `static let` in a `@MainActor` type IS actor-isolated, and this is the default
/// argument of the `nonisolated` decision function below, which could not then reach it. Same reason
/// `legacyTailKey` further down carries the keyword.
nonisolated static let publishCoalesceSeconds: Double = 0.25

/// What the coalescer should do, given when it last published and whether a flush is already queued.
///
/// Pure, so the policy is tested without a clock or a run loop: the async half below is then a thin
/// adapter with no decisions of its own. Leading edge plus a trailing flush, which is what makes the
/// contract "the last line of a burst always lands" rather than "the last line is dropped until the next
/// one arrives". (#2547)
/// `Equatable` compares the `scheduleIn` payload EXACTLY, and it is the result of floating-point
/// subtraction, so a test asserting a whole expected case is comparing doubles for equality. Destructure
/// and use an accuracy instead: `0.25 - (100.10 - 100)` is `0.15000000000000568`, not `0.15`.
enum LogPublishDecision: Equatable {
/// Enough time has passed; publish on this line.
case publishNow
/// Inside the window with nothing queued; publish once after this many seconds.
case scheduleIn(Double)
/// Inside the window and a flush is already queued, which will cover this line.
case alreadyQueued
}

nonisolated static func logPublishDecision(
now: Double, lastPublish: Double, flushQueued: Bool, interval: Double = publishCoalesceSeconds,
) -> LogPublishDecision {
let elapsed = now - lastPublish
if elapsed >= interval { return .publishNow }
if flushQueued { return .alreadyQueued }
// Clamped into [0, interval]. A clock that went backwards must neither ask for a negative sleep nor
// stall the log for longer than one window: without the upper clamp a `lastPublish` in the future
// makes `interval - elapsed` exceed the interval, and the log would sit un-notified for that long.
return .scheduleIn(min(interval, max(0, interval - elapsed)))
}

private var lastLogPublish: Double = -.greatestFiniteMagnitude
private var logFlushQueued = false

/// Bump `logRevision` now, or once at the end of the current window.
private func publishLogCoalesced() {
let now = ProcessInfo.processInfo.systemUptime
switch Self.logPublishDecision(now: now, lastPublish: lastLogPublish, flushQueued: logFlushQueued) {
case .alreadyQueued:
return
case .publishNow:
lastLogPublish = now
logRevision &+= 1
case .scheduleIn(let wait):
logFlushQueued = true
Task { @MainActor [weak self] in
// `try?` and NOT an early return on failure, deliberately. The flag is what suppresses every
// other publish in the window, so the one thing this closure must always do is clear it. A
// cancelled sleep throws; swallowing that and falling through still clears the flag and
// publishes. Rewriting this as `try await` with the error propagating would leave the flag
// set forever, and the log would keep capturing while the UI silently froze.
try? await Task.sleep(nanoseconds: UInt64(wait * 1_000_000_000))
guard let self else { return }
self.logFlushQueued = false
self.lastLogPublish = ProcessInfo.processInfo.systemUptime
self.logRevision &+= 1
}
}
}

/// The in-app log lines tagged for one test domain (for the Test Centre live readout). Read-only,
/// no side effects; the prefix is the same one `append(log:domain:)` writes, and redaction never
/// strips it (the tag is prepended before the scrub, which only touches identifiers). (Group E)
Expand Down
5 changes: 4 additions & 1 deletion Strand/Screens/LiveView.swift
Original file line number Diff line number Diff line change
Expand Up @@ -1351,7 +1351,10 @@ private struct LiveLogCard: View {
.scrollBounceBehavior(.basedOnSize, axes: .horizontal)
#endif
.frame(height: 200)
.onChangeCompat(of: live.log.count) { _ in
// On `logRevision`, not `log.count` (#2547). The revision is monotonic and ticks exactly once per
// coalesced publish; the count plateaus while the ring trims, so it can stay equal across an
// append and skip a scroll.
.onChangeCompat(of: live.logRevision) { _ in
if let last = live.log.indices.last { proxy.scrollTo(last, anchor: .bottom) }
}
}
Expand Down
2 changes: 1 addition & 1 deletion Strand/Screens/TestCentreView.swift
Original file line number Diff line number Diff line change
Expand Up @@ -903,7 +903,7 @@ private struct TestModeRow: View {
/// The HONEST per-mode captured-day count for a guided row (#965): distinct days THIS mode produced its
/// own trace on, read from the same shareable log the report exports, so each active mode accumulates
/// its OWN count instead of every guided row sharing one elapsed-clock number. nil for a toggle mode
/// (no "K of N") and when the mode is off. Recomputes with `live.log` (published) so the row updates as
/// (no "K of N") and when the mode is off. Recomputes with `live.log`, which the coalesced `logRevision` invalidates (#2547), so the row updates as
/// new capture days land.
private var capturedUnits: Int? {
guard on, case .guided = mode.capture else { return nil }
Expand Down
124 changes: 124 additions & 0 deletions StrandTests/LogPublishCoalesceTests.swift
Original file line number Diff line number Diff line change
@@ -0,0 +1,124 @@
import XCTest
@testable import Strand

/// The strap log publishes at most four times a second, however fast lines arrive, and never loses one.
///
/// #2547: `LiveState` carries dozens of `@Published` properties on one `ObservableObject`, and an
/// `ObservableObject` invalidates EVERY observer on ANY published change. Publishing per appended line
/// therefore woke every view in the app for each line, and a history drain plus a re-score burst emits
/// hundreds a minute. That was the invalidation half of the #2521 background CPU kill; #2546 cut the cost of
/// each invalidation, this cuts how many there are. The Android twin has throttled this for a while, via
/// `boundedRevision(ble.logRevision, coalesceMs = 250)`.
///
/// The decision is a pure function so the policy is pinned without a clock or a run loop. The async adapter
/// around it makes no decisions of its own.
final class LogPublishCoalesceTests: XCTestCase {

private let interval = 0.25

/// The first line after an idle gap publishes immediately: a leading edge, so a live log does not sit a
/// quarter second behind on its first line.
func testTheFirstLineAfterAGapPublishesImmediately() {
XCTAssertEqual(
LiveState.logPublishDecision(now: 100, lastPublish: 99, flushQueued: false, interval: interval),
.publishNow)
}

/// Never published yet. The sentinel is a very negative number, so this must not overflow into a wait.
func testAFreshStatePublishesItsFirstLine() {
XCTAssertEqual(
LiveState.logPublishDecision(now: 0, lastPublish: -.greatestFiniteMagnitude,
flushQueued: false, interval: interval),
.publishNow)
}

/// A second line inside the window does not publish; it queues one flush for the end of the window.
///
/// Destructured with an accuracy rather than compared as a whole case: the payload is the result of a
/// floating-point subtraction, and `0.25 - (100.10 - 100)` is `0.15000000000000568`, so asserting
/// `.scheduleIn(0.15)` compares two unequal doubles and fails.
func testALineInsideTheWindowSchedulesTheRemainder() {
guard case .scheduleIn(let wait) = LiveState.logPublishDecision(
now: 100.10, lastPublish: 100, flushQueued: false, interval: interval) else {
return XCTFail("a line 0.10s into the window should schedule the remainder")
}
XCTAssertEqual(wait, 0.15, accuracy: 1e-9)
}

/// Every further line in the same window is covered by the flush already queued. THIS is the coalescing:
/// a hundred lines in one window still produce one publish.
func testFurtherLinesInTheWindowAddNothing() {
for offset in [0.11, 0.12, 0.2, 0.249] {
XCTAssertEqual(
LiveState.logPublishDecision(now: 100 + offset, lastPublish: 100,
flushQueued: true, interval: interval),
.alreadyQueued, "offset \(offset)")
}
}

/// The boundary belongs to publishNow, so a steady stream at exactly the interval keeps publishing
/// rather than queueing a flush per line and doubling the work.
///
/// Uses exactly-representable values (1.0, 1.25, 0.25 are all exact in binary) so the boundary is tested
/// on the real rule rather than on whether a particular subtraction happened to round favourably.
func testTheBoundaryPublishesRatherThanSchedules() {
XCTAssertEqual(
LiveState.logPublishDecision(now: 1.25, lastPublish: 1.0, flushQueued: false, interval: 0.25),
.publishNow)
}

/// A clock that goes backwards must neither ask for a negative sleep nor stall longer than one window.
///
/// The upper bound is the half that needed an implementation fix: `interval - elapsed` with a
/// `lastPublish` in the future exceeds the interval, so without clamping the log would sit un-notified
/// for 0.45s here instead of 0.25s.
func testABackwardClockNeverSchedulesAnOutOfRangeWait() {
guard case .scheduleIn(let wait) = LiveState.logPublishDecision(
now: 100, lastPublish: 100.20, flushQueued: false, interval: interval) else {
return XCTFail("a now before lastPublish is inside the window, so it should schedule")
}
XCTAssertGreaterThanOrEqual(wait, 0)
XCTAssertLessThanOrEqual(wait, interval)
}

/// The one that matters: capture is per line whatever the publish does.
///
/// Coalescing the CAPTURE instead of the notification would lose log lines, which is the whole risk of
/// this change, and the many tests that append and then inspect `live.log` in the same turn depend on the
/// read staying synchronous.
@MainActor
func testEveryLineIsCapturedSynchronouslyDespiteTheCoalescedPublish() {
let live = LiveState()
for i in 0..<50 { live.append(log: "coalesce-probe \(i)") }
let mine = live.log.filter { $0.contains("coalesce-probe") }
XCTAssertEqual(mine.count, 50, "every appended line must be readable immediately")
XCTAssertEqual(mine.first, "coalesce-probe 0")
XCTAssertEqual(mine.last, "coalesce-probe 49")
}

/// And the point of the exercise: fifty lines in one window are ONE publish, not fifty.
///
/// Synchronous because the leading edge publishes on the first line and the remaining forty-nine fall
/// inside the window, so no waiting is needed to observe the count. Reverting to a per-line publish makes
/// this fifty.
@MainActor
func testFiftyLinesInOneWindowPublishOnce() {
let live = LiveState()
XCTAssertEqual(live.logRevision, 0, "a fresh state has not published")
for i in 0..<50 { live.append(log: "coalesce-probe \(i)") }
XCTAssertEqual(live.logRevision, 1,
"one leading-edge publish should cover the whole burst, got \(live.logRevision)")
}

/// A queued flush never starves: whatever the line rate, the decision is only ever `alreadyQueued` while
/// one is outstanding, and the adapter clears the flag when it fires. Pinning that the flag is the ONLY
/// thing suppressing a publish, so a stuck flag is the single failure mode to look for.
func testOnlyAQueuedFlushSuppressesAPublish() {
let queued = LiveState.logPublishDecision(now: 100.1, lastPublish: 100,
flushQueued: true, interval: interval)
let notQueued = LiveState.logPublishDecision(now: 100.1, lastPublish: 100,
flushQueued: false, interval: interval)
XCTAssertEqual(queued, .alreadyQueued)
XCTAssertNotEqual(notQueued, .alreadyQueued)
}
}
Loading