- Use monotonic import timeout timing
- Browse files
-
bogdan committed a day ago
Showing 4 changed files
with
54 additions
and
23 deletions
+7
-5
HealthProbe/Doc/04-project/Import-Optimization-Log.md
@@ -601,6 +601,7 @@ rows exist". |
||
| 601 | 601 |
| 2026-06-05 | `0db2f5e` | Skip legacy compact archive rebuild for SQLite-backed deltas. | Confirmed on two full-profile repeated captures. First report, `buildFingerprint: 1.0(1)-1780689289-92064`, completed in `6.2s` with `127/127` complete, `CaptureModes: unchangedDelta=118, delta=9`, `DeltaEvents: 116`, `SummedProcessingElapsed: 0.0s`, and `SummedProcessingRecordArchiveRebuildElapsed: 0.0s`; Heart Rate and Active Energy each completed in `0.2s` with no rebuild. Second report, `buildFingerprint: 1.0(1)-1780689890-92064`, completed in `5.8s` with `CaptureModes: unchangedDelta=121, delta=6`, `DeltaEvents: 7`, fetch `2.0s`, insert `0.1s`, finalize `1.7s`, residual `1.1s`, and processing/rebuild still `0.0s`. Conclusion: the legacy compact archive rebuild was the repeated-capture bottleneck and is now removed from the normal SQLite-backed delta path; the repeated full-profile floor is now roughly `6s` on this device/database. | |
| 602 | 602 |
| 2026-06-06 | `fbbca81` | Expose saved diagnostic reports in Settings. | Diagnostic reports were already persisted under Application Support at snapshot completion, but they were not discoverable from the app after dismissing the result sheet. Settings now lists the latest saved reports, opens them with the same chunked lazy diagnostics viewer, supports copy, and allows per-report deletion. Expected signal: future import analysis can recover the exact report text after the fact instead of depending on screenshots or manual copy at completion time. | |
| 603 | 603 |
| 2026-06-06 | `92592cd` | Stop HealthKit date-boundary queries on timeout cancellation. | A restored-device report with `buildFingerprint: 1.0(1)-1780695759-92064` recorded `263m 4s` total and `262m 50s` fetch for `Zinc`, with both `earliest_sample` and `latest_sample` reported as timeout after `15770.00s` despite `timeoutConfigured: 15.0s`. This timing is not a clean import-duration measurement: the phone had already been unresponsive for roughly `4h22m`, while the app/snapshot attempt was started shortly before the report. The report still exposed a defensive gap: date-boundary queries used plain continuations, so cancellation could mark timeout without explicitly stopping the underlying `HKSampleQuery`. Date-boundary queries now use the cancellable HealthKit continuation box and call `HKHealthStore.stop(_:)` when the timeout cancels the task. Expected signal: if a future boundary query wedges, it should fail near its configured timeout and leave the rest of the capture able to continue; do not use the `263m` value as a throughput datapoint. | |
| 604 |
+| 2026-06-06 | pending | Use monotonic import timers and non-blocking per-query timeout race. | Follow-up review clarified that the app and phone had been restarted before the suspicious report, so a persisted armed timer should not be assumed. Code inspection found no persisted deadline/start timer, only adaptive timeout profiles. However, import durations and API-call diagnostics used `Date()` wall-clock deltas, which can jump after system time or device-state changes, and the per-query timeout helper used a structured task group that could wait for a stuck operation child after timeout. User-visible snapshot duration, per-type total elapsed, boundary fetch elapsed, and API-call elapsed now use a `DispatchTime` monotonic timer. Per-query timeout now races unstructured operation/timeout tasks so the timeout path can return after cancelling the operation while the HealthKit cancellation handler stops the underlying query. Expected signal: after reboot or Health UI instability, diagnostics should not inherit impossible multi-hour elapsed values from wall-clock jumps, and a wedged boundary query should report near the configured timeout. | |
|
| 604 | 605 |
|
| 605 | 606 |
## Current Diagnosis |
| 606 | 607 |
|
@@ -820,11 +821,12 @@ The likely bottleneck is per-row SQLite work: |
||
| 820 | 821 |
operator remembering to copy the visible report. Saved reports are now exposed |
| 821 | 822 |
in Settings so the exact text can be recovered later. |
| 822 | 823 |
- A timeout report with elapsed time far above `timeoutConfigured` can indicate |
| 823 |
- either a stale/invalid timing baseline after device unresponsiveness or an |
|
| 824 |
- underlying HealthKit query that was not stopped on task cancellation. |
|
| 825 |
- Date-boundary queries now explicitly stop their `HKSampleQuery` on |
|
| 826 |
- cancellation; future reports should be judged by whether the elapsed time is |
|
| 827 |
- near the configured timeout. |
|
| 824 |
+ either a wall-clock timing artifact after device unresponsiveness/system time |
|
| 825 |
+ changes or an underlying HealthKit query that was not stopped on task |
|
| 826 |
+ cancellation. Operational import timings now use monotonic uptime, and |
|
| 827 |
+ date-boundary queries explicitly stop their `HKSampleQuery` on cancellation. |
|
| 828 |
+ Future reports should be judged by whether the elapsed time is near the |
|
| 829 |
+ configured timeout. |
|
| 828 | 830 |
- After a completed import, the app may remain unresponsive or crash in legacy |
| 829 | 831 |
post-import cache work. A 2026-06-03 console log showed Heart Rate and Active |
| 830 | 832 |
Energy `TypeCount.detailCacheData` precompute immediately before a Core Data |
+28
-17
HealthProbe/Services/HealthKitService.swift
@@ -793,7 +793,7 @@ final class HealthKitService {
|
||
| 793 | 793 |
archiveObservationID: Int64, |
| 794 | 794 |
progress: SnapshotFetchProgress? = nil |
| 795 | 795 |
) async -> TypeCountFetchResult {
|
| 796 |
- let started = Date() |
|
| 796 |
+ let timer = MonotonicTimer() |
|
| 797 | 797 |
progress?.updateStatus(monitoredType.id, status: .fetching) |
| 798 | 798 |
|
| 799 | 799 |
// Unsupported type: HKObjectType factory returned nil for this identifier |
@@ -816,7 +816,7 @@ final class HealthKitService {
|
||
| 816 | 816 |
records: [], |
| 817 | 817 |
recordArchiveData: nil |
| 818 | 818 |
) |
| 819 |
- result.totalElapsedSeconds = Date().timeIntervalSince(started) |
|
| 819 |
+ result.totalElapsedSeconds = timer.elapsedSeconds |
|
| 820 | 820 |
result.timeoutConfiguredSeconds = timeoutSeconds |
| 821 | 821 |
result.applyTimeoutProfile(timeoutProfile) |
| 822 | 822 |
progress?.updateDetails(from: result) |
@@ -832,7 +832,7 @@ final class HealthKitService {
|
||
| 832 | 832 |
archiveObservationID: archiveObservationID, |
| 833 | 833 |
progress: progress |
| 834 | 834 |
) |
| 835 |
- result.totalElapsedSeconds = Date().timeIntervalSince(started) |
|
| 835 |
+ result.totalElapsedSeconds = timer.elapsedSeconds |
|
| 836 | 836 |
result.timeoutConfiguredSeconds = timeoutSeconds |
| 837 | 837 |
result.applyTimeoutProfile(timeoutProfile) |
| 838 | 838 |
progress?.updateDetails(from: result) |
@@ -858,11 +858,10 @@ final class HealthKitService {
|
||
| 858 | 858 |
archiveObservationID: Int64, |
| 859 | 859 |
progress: SnapshotFetchProgress? |
| 860 | 860 |
) async -> TypeCountFetchResult {
|
| 861 |
- let dateFetchStartedAt = Date() |
|
| 862 |
- let dateDeadline = Date().addingTimeInterval(timeoutSeconds) |
|
| 861 |
+ let dateFetchTimer = MonotonicTimer() |
|
| 863 | 862 |
async let earliestTask = measureAPICall( |
| 864 | 863 |
queryType: "earliest_sample", |
| 865 |
- timeoutSeconds: max(0, dateDeadline.timeIntervalSinceNow) |
|
| 864 |
+ timeoutSeconds: timeoutSeconds |
|
| 866 | 865 |
) {
|
| 867 | 866 |
try await self.fetchEarliestDate(for: sampleType) |
| 868 | 867 |
} resultDescription: { date in
|
@@ -870,7 +869,7 @@ final class HealthKitService {
|
||
| 870 | 869 |
} |
| 871 | 870 |
async let latestTask = measureAPICall( |
| 872 | 871 |
queryType: "latest_sample", |
| 873 |
- timeoutSeconds: max(0, dateDeadline.timeIntervalSinceNow) |
|
| 872 |
+ timeoutSeconds: timeoutSeconds |
|
| 874 | 873 |
) {
|
| 875 | 874 |
try await self.fetchLatestDate(for: sampleType) |
| 876 | 875 |
} resultDescription: { date in
|
@@ -879,7 +878,7 @@ final class HealthKitService {
|
||
| 879 | 878 |
let earliestResult = await earliestTask |
| 880 | 879 |
let latestResult = await latestTask |
| 881 | 880 |
var apiCalls = [earliestResult.apiCall, latestResult.apiCall] |
| 882 |
- let dateFetchElapsedSeconds = Date().timeIntervalSince(dateFetchStartedAt) |
|
| 881 |
+ let dateFetchElapsedSeconds = dateFetchTimer.elapsedSeconds |
|
| 883 | 882 |
|
| 884 | 883 |
guard earliestResult.apiCall.status == .complete, latestResult.apiCall.status == .complete else {
|
| 885 | 884 |
let status = firstImpairedStatus(in: apiCalls) |
@@ -2075,7 +2074,7 @@ final class HealthKitService {
|
||
| 2075 | 2074 |
operation: @escaping @Sendable () async throws -> Value, |
| 2076 | 2075 |
resultDescription: @escaping @Sendable (Value) -> String |
| 2077 | 2076 |
) async -> APICallMeasurement<Value> {
|
| 2078 |
- let started = Date() |
|
| 2077 |
+ let timer = MonotonicTimer() |
|
| 2079 | 2078 |
do {
|
| 2080 | 2079 |
let value: Value |
| 2081 | 2080 |
if let timeoutSeconds {
|
@@ -2092,7 +2091,7 @@ final class HealthKitService {
|
||
| 2092 | 2091 |
apiCall: HealthKitAPICallResult( |
| 2093 | 2092 |
queryType: queryType, |
| 2094 | 2093 |
status: .complete, |
| 2095 |
- elapsedSeconds: Date().timeIntervalSince(started), |
|
| 2094 |
+ elapsedSeconds: timer.elapsedSeconds, |
|
| 2096 | 2095 |
resultValue: resultDescription(value) |
| 2097 | 2096 |
) |
| 2098 | 2097 |
) |
@@ -2104,7 +2103,7 @@ final class HealthKitService {
|
||
| 2104 | 2103 |
apiCall: HealthKitAPICallResult( |
| 2105 | 2104 |
queryType: queryType, |
| 2106 | 2105 |
status: failure.status, |
| 2107 |
- elapsedSeconds: Date().timeIntervalSince(started), |
|
| 2106 |
+ elapsedSeconds: timer.elapsedSeconds, |
|
| 2108 | 2107 |
resultValue: nil, |
| 2109 | 2108 |
errorCode: failure.errorCode ?? "\(nsError.code)", |
| 2110 | 2109 |
errorDomain: failure.errorDomain ?? nsError.domain, |
@@ -2274,12 +2273,24 @@ final class HealthKitService {
|
||
| 2274 | 2273 |
// MARK: - Timeout utility |
| 2275 | 2274 |
|
| 2276 | 2275 |
private func withTimeout<T: Sendable>(seconds: TimeInterval, operation: @escaping @Sendable () async throws -> T) async throws -> T {
|
| 2277 |
- try await withThrowingTaskGroup(of: T.self) { group in
|
|
| 2278 |
- group.addTask { try await operation() }
|
|
| 2279 |
- group.addTask {
|
|
| 2280 |
- try await Task.sleep(nanoseconds: UInt64(seconds * 1_000_000_000)) |
|
| 2281 |
- throw CancellationError() |
|
| 2282 |
- } |
|
| 2276 |
+ guard seconds > 0, seconds.isFinite else { throw CancellationError() }
|
|
| 2277 |
+ let nanoseconds = UInt64((seconds * 1_000_000_000).rounded(.up)) |
|
| 2278 |
+ let operationTask = Task {
|
|
| 2279 |
+ try await operation() |
|
| 2280 |
+ } |
|
| 2281 |
+ let timeoutTask = Task<T, Error> {
|
|
| 2282 |
+ try await Task.sleep(nanoseconds: nanoseconds) |
|
| 2283 |
+ operationTask.cancel() |
|
| 2284 |
+ throw CancellationError() |
|
| 2285 |
+ } |
|
| 2286 |
+ defer {
|
|
| 2287 |
+ operationTask.cancel() |
|
| 2288 |
+ timeoutTask.cancel() |
|
| 2289 |
+ } |
|
| 2290 |
+ |
|
| 2291 |
+ return try await withThrowingTaskGroup(of: T.self) { group in
|
|
| 2292 |
+ group.addTask { try await operationTask.value }
|
|
| 2293 |
+ group.addTask { try await timeoutTask.value }
|
|
| 2283 | 2294 |
do {
|
| 2284 | 2295 |
let result = try await group.next()! |
| 2285 | 2296 |
group.cancelAll() |
+16
-0
HealthProbe/Utilities/MonotonicTimer.swift
@@ -0,0 +1,16 @@ |
||
| 1 |
+import Dispatch |
|
| 2 |
+import Foundation |
|
| 3 |
+ |
|
| 4 |
+struct MonotonicTimer: Sendable {
|
|
| 5 |
+ private let startedAtNanoseconds: UInt64 |
|
| 6 |
+ |
|
| 7 |
+ init() {
|
|
| 8 |
+ startedAtNanoseconds = DispatchTime.now().uptimeNanoseconds |
|
| 9 |
+ } |
|
| 10 |
+ |
|
| 11 |
+ var elapsedSeconds: TimeInterval {
|
|
| 12 |
+ let now = DispatchTime.now().uptimeNanoseconds |
|
| 13 |
+ guard now >= startedAtNanoseconds else { return 0 }
|
|
| 14 |
+ return TimeInterval(now - startedAtNanoseconds) / 1_000_000_000 |
|
| 15 |
+ } |
|
| 16 |
+} |
|
+3
-1
HealthProbe/ViewModels/DashboardViewModel.swift
@@ -32,6 +32,7 @@ final class DashboardViewModel {
|
||
| 32 | 32 |
private var pendingPartialSnapshotID: UUID? |
| 33 | 33 |
private var pendingAmbiguousSnapshotID: UUID? |
| 34 | 34 |
private var archiveCacheRefreshTask: Task<Void, Never>? |
| 35 |
+ private var fetchTimer: MonotonicTimer? |
|
| 35 | 36 |
|
| 36 | 37 |
private struct ArchiveCacheRefreshResult: Sendable {
|
| 37 | 38 |
let observationRows: [CachedArchiveObservationRow] |
@@ -70,6 +71,7 @@ final class DashboardViewModel {
|
||
| 70 | 71 |
snapshotProgress = .fetching |
| 71 | 72 |
showProgressSheet = true |
| 72 | 73 |
fetchStartDate = Date() |
| 74 |
+ fetchTimer = MonotonicTimer() |
|
| 73 | 75 |
fetchDurationSeconds = nil |
| 74 | 76 |
operationID = UUID() |
| 75 | 77 |
completedSnapshotID = nil |
@@ -117,7 +119,7 @@ final class DashboardViewModel {
|
||
| 117 | 119 |
) |
| 118 | 120 |
} |
| 119 | 121 |
|
| 120 |
- fetchDurationSeconds = fetchStartDate.map { Date().timeIntervalSince($0) }
|
|
| 122 |
+ fetchDurationSeconds = fetchTimer?.elapsedSeconds |
|
| 121 | 123 |
applyOutcome(capture.outcome) |
| 122 | 124 |
fetchProgress?.updateChainContext( |
| 123 | 125 |
previousSnapshotID: capture.outcome.previousSnapshotID, |