From 4005364cf2c91b0ff8fe5998c4e538c91a915b3d Mon Sep 17 00:00:00 2001 From: Iskren Alexandrov Date: Thu, 17 Sep 2026 12:27:07 +0300 Subject: [PATCH] feat(rescore): log a pass's CPU time and assertion expiries beside its elapsed time --- Strand/Data/IntelligenceEngine.swift | 7 +++++ .../System/RescoreBackgroundScheduler.swift | 29 +++++++++++++++++++ .../RescoreBackgroundSchedulerTests.swift | 19 +++++++++++- 3 files changed, 54 insertions(+), 1 deletion(-) diff --git a/Strand/Data/IntelligenceEngine.swift b/Strand/Data/IntelligenceEngine.swift index 650516760d..864c6d1872 100644 --- a/Strand/Data/IntelligenceEngine.swift +++ b/Strand/Data/IntelligenceEngine.swift @@ -735,6 +735,8 @@ final class IntelligenceEngine: ObservableObject { // also counts every minute the process spent suspended mid-pass. One overnight pass suspended by a // sleeping phone banked 19 003 s, which then deferred every background re-score after it. let reScoreStart = DispatchTime.now().uptimeNanoseconds + let reScoreCPUStart = RescoreBackgroundScheduler.processCPUSeconds() + let reScoreExpiriesAtStart = RescoreBackgroundScheduler.assertionExpiries computing = true // #1538: the pass is now past every gate and will do real work. Mark it started durably, so that a // process killed mid-pass leaves evidence a LATER process can read — the killed process itself gets @@ -2851,6 +2853,11 @@ final class IntelligenceEngine: ObservableObject { let elapsed = Double(DispatchTime.now().uptimeNanoseconds &- reScoreStart) / 1_000_000_000 let settled = RescoreBackgroundScheduler.markRescoreCompleted(seconds: elapsed, owedToken: owedToken) diagnosticSink?("re-score: done — scored \(scoredNights.count) night(s) in \(Int(elapsed * 1000)) ms (#1005)", nil) + diagnosticSink?(RescoreBackgroundScheduler.passCostLogLine( + cpuSeconds: RescoreBackgroundScheduler.processCPUSeconds().flatMap { end in reScoreCPUStart.map { end - $0 } }, + elapsedSeconds: elapsed, + assertionExpiries: RescoreBackgroundScheduler.assertionExpiries - reScoreExpiriesAtStart, + backgroundedAtEnd: RescoreBackgroundScheduler.isBackgrounded), nil) // #1681: a pass that completes while leaving the mark SET looks identical in a capture to one that // cleared it. Rare-event evidence, so always-on: it costs a line only when it actually happens, // and it is exactly what is missing when someone reports the app re-scoring on every launch. diff --git a/Strand/System/RescoreBackgroundScheduler.swift b/Strand/System/RescoreBackgroundScheduler.swift index 731536e21f..491bca141f 100644 --- a/Strand/System/RescoreBackgroundScheduler.swift +++ b/Strand/System/RescoreBackgroundScheduler.swift @@ -197,6 +197,34 @@ enum RescoreBackgroundScheduler { } } + /// How many times the re-score execution assertion has expired in this process. A pass reads it at its + /// start and end, so its cost line can say whether it outlived its background grant. + private(set) static var assertionExpiries = 0 + + /// CPU seconds this process has used, user plus system, across all threads. Process-wide, so it includes + /// the BLE and UI work beside a pass; nil if the kernel refuses the read. + nonisolated static func processCPUSeconds() -> Double? { + var usage = rusage() + guard getrusage(RUSAGE_SELF, &usage) == 0 else { return nil } + func seconds(_ t: timeval) -> Double { Double(t.tv_sec) + Double(t.tv_usec) / 1_000_000 } + return seconds(usage.ru_utime) + seconds(usage.ru_stime) + } + + /// What a completed pass cost, and whether it outlived its background grant. + /// + /// The `re-score: done` duration is uptime, which keeps running while the process is suspended, so on + /// its own it cannot separate a pass that was suspended and resumed across wakes from one that ran on + /// past an expired assertion. CPU time beside it can: a pass that spends a small fraction of its elapsed + /// time on CPU was mostly suspended, and `expired` says whether the assertion ran out on the way. + nonisolated static func passCostLogLine(cpuSeconds: Double?, elapsedSeconds: Double, + assertionExpiries: Int, backgroundedAtEnd: Bool) -> String { + let cpu = cpuSeconds.map { String(format: "%.1fs", max(0, $0)) } ?? "n/a" + let share = cpuSeconds.flatMap { elapsedSeconds > 0 ? Int((max(0, $0) / elapsedSeconds * 100).rounded()) : nil } + return "re-score: cost cpu=\(cpu) elapsed=\(String(format: "%.1f", elapsedSeconds))s" + + " cpuShare=\(share.map { "\($0)%" } ?? "n/a") assertionExpired=\(assertionExpiries)" + + " backgrounded=\(backgroundedAtEnd)" + } + /// Rest after a unit of re-score work when backgrounded, so the pass stays under iOS's background CPU /// limit instead of being killed by it (`RescoreBackgroundPolicy.backgroundRestPerWorkSecond`). `mark` is /// the uptime the unit started at, in nanoseconds; it is reset to the end of the rest for the next unit. @@ -221,6 +249,7 @@ enum RescoreBackgroundScheduler { // the owed mark is still set (only a completed pass clears it) and that is what the next // decision reads. MainActor.assumeIsolated { + assertionExpiries += 1 log("re-score: background time expired mid-pass — it resumes on the next wake (#1538)") schedule() assertion.end() diff --git a/StrandTests/RescoreBackgroundSchedulerTests.swift b/StrandTests/RescoreBackgroundSchedulerTests.swift index 9218597bd9..e7cd43a06e 100644 --- a/StrandTests/RescoreBackgroundSchedulerTests.swift +++ b/StrandTests/RescoreBackgroundSchedulerTests.swift @@ -314,5 +314,22 @@ final class RescoreBackgroundSchedulerTests: XCTestCase { let latest = RescoreBackgroundScheduler.markRescoreOwed() XCTAssertTrue(RescoreBackgroundScheduler.markRescoreCompleted(seconds: 1, owedToken: latest)) } -} + func testThePassCostLineSeparatesASuspendedPassFromABusyOne() { + // The field shape: 2 h 27 min of uptime for a pass that is ~2 min of CPU when run in the foreground. + XCTAssertEqual(RescoreBackgroundScheduler.passCostLogLine(cpuSeconds: 150, elapsedSeconds: 8_813.2, + assertionExpiries: 1, backgroundedAtEnd: true), + "re-score: cost cpu=150.0s elapsed=8813.2s cpuShare=2% assertionExpired=1 backgrounded=true") + XCTAssertEqual(RescoreBackgroundScheduler.passCostLogLine(cpuSeconds: nil, elapsedSeconds: 3, + assertionExpiries: 0, backgroundedAtEnd: false), + "re-score: cost cpu=n/a elapsed=3.0s cpuShare=n/a assertionExpired=0 backgrounded=false") + } + + func testProcessCPUTimeAdvances() { + let start = RescoreBackgroundScheduler.processCPUSeconds() ?? 0 + var x = 0.0 + for i in 0..<2_000_000 { x += sin(Double(i)) } + XCTAssertNotEqual(x, 0) + XCTAssertGreaterThan(RescoreBackgroundScheduler.processCPUSeconds() ?? 0, start) + } +}