feat(rescore): log a pass's CPU time and assertion expiries beside its elapsed time

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.

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()

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