Showing 4 changed files with 76 additions and 11 deletions
+17 -5
HealthProbe/Doc/04-project/Import-Optimization-Log.md
@@ -31,6 +31,7 @@ Use the HealthProbe diagnostic report fields below for comparisons:
31 31
 | `WallClockDuration` / `Duration` | User-visible total operation time. |
32 32
 | `SummedFetchElapsed` | Time spent fetching HealthKit samples. Per-metric sums may overlap. |
33 33
 | `SummedProcessingElapsed` | Time spent converting HealthKit samples into archive rows. |
34
+| `SummedProcessingRecordArchiveRebuildElapsed` | Time spent rebuilding legacy compact record archives during delta captures. |
34 35
 | `SummedInsertElapsed` | Time spent writing rows to SQLite. Current main bottleneck. |
35 36
 | `SummedFinalizeElapsed` | Type verification, aggregate rebuild, and finalization cost. |
36 37
 | Per-type `insertElapsed` | Most useful field for high-volume types such as Heart Rate and Active Energy. |
@@ -595,7 +596,8 @@ rows exist".
595 596
 | 2026-06-04 | older build / schema v2 | Captured large first-import baseline on a bigger device database. | Initial full-profile snapshot on an older build completed with `127/127` metrics and `8,421,978` records, but it used `reportSchemaVersion: 2` and has no build fingerprint. Treat it as a volume/shape baseline, not a precise current-build comparison. Wall clock was `166m10s`; summed fetch `5m19s`, processing `20m29s`, insert `137m31s`, finalize `1m53s`. The high-volume types dominated: Heart Rate `2,225,738` records and `46m57s` total (`39m16s` insert), Active Energy `1,914,449` records and `41m35s` total (`35m21s` insert), another high-volume type around `2,007,920` records and `41m20s` total (`34m29s` insert), and Basal Energy `1,116,074` records and `21m37s` total (`17m48s` insert). Conclusion: for clean first imports on very large databases, SQLite insert/index/write-path cost remains the central risk; incremental daily-aggregate optimization should not add first-import indexes without measurement. |
596 597
 | 2026-06-05 | `6041bac` | Split daily aggregate finalization timings. | The first finalization phase report identified daily aggregate work as the remaining changed-type bottleneck, but `finalizeDailyAggregateElapsed` still mixed affected-bucket lookup, previous aggregate copy, destination delete, affected-bucket rebuild, replacement insert, and residual SQL/transaction overhead. Diagnostics now emit aggregate and per-type daily subphase fields: bucket lookup, copy, delete, rebuild, insert, and other. Follow-up report with `buildFingerprint: 1.0(1)-1780618540-92064` completed in `23.5s`, with `127/127` complete, `CaptureModes: unchangedDelta=118, delta=9`, and `DeltaEvents: 97`. Finalization was `10.5s`, daily aggregate work was `7.4s`, and daily rebuild alone was `6.9s`; daily copy was only `0.5s`. Heart Rate had `40` delta events and spent `4.8s` finalizing, of which `3.8s` was daily aggregate rebuild. Conclusion: copying previous materialized daily rows is not the bottleneck; affected-bucket rebuild scans are. |
597 598
 | 2026-06-05 | `bf5a861` | Rebuild changed daily aggregate buckets from time-ranged versions. | Confirmed on two full-profile repeated captures with `buildFingerprint: 1.0(1)-1780640325-92064`. The overnight-data run completed in `21.8s` with `127/127` complete, `CaptureModes: unchangedDelta=111, delta=16`, and `DeltaEvents: 322`; daily aggregate rebuild dropped from `6.9s` to `0.0s`, with daily aggregate work now only `0.6s` copy. The low-delta run completed in `6.6s` with `CaptureModes: unchangedDelta=125, delta=2`; daily aggregate rebuild again stayed `0.0s`. Conclusion: the time-ranged `sample_versions(start_date, sample_id)` query solved the affected-bucket rebuild bottleneck. Continue monitoring first-import insert timing because the new index is a write-path tradeoff. |
598
-| 2026-06-05 | pending | Count observation events from the event table first. | After `bf5a861`, remaining finalization cost moved to event-count / previous-summary lookup: `2.5s` on the overnight-data run and `0.2s` on low-delta. `eventCounts` still started from `samples` filtered by type, which can scan a high-volume type to count a few events. The query now starts from `sample_observation_events(observation_id, event_kind)` and joins to `samples` only to filter type. Expected signal: lower `SummedFinalizeEventCountElapsed`, especially Heart Rate's `0.9s` and Cycling Distance's `0.7s` in the overnight report. |
599
+| 2026-06-05 | `e7d45a2` | Count observation events from the event table first. | Confirmed on a full-profile repeated capture with `buildFingerprint: 1.0(1)-1780646299-92064`: wall clock `15.6s`, `127/127` complete, `CaptureModes: unchangedDelta=114, delta=13`, and `DeltaEvents: 99`. `SummedFinalizeEventCountElapsed` dropped from the post-`bf5a861` overnight baseline `2.5s` to `0.0s`; total finalize dropped to `1.7s`, while daily aggregate rebuild stayed `0.0s`. Remaining cost is processing: `9.1s` total, led by Heart Rate `4.6s` for `18` events, Active Energy `1.8s` for `11` events, and Basal Energy `1.5s` for `5` events. |
600
+| 2026-06-05 | pending | Split processing timing diagnostics. | With finalization reduced to `1.7s`, `SummedProcessingElapsed` is the active repeated-capture bottleneck. Diagnostics now split processing into delta apply, compact record archive rebuild, initial record processing, compact archive/hash finalization, and other. Expected signal: quantify how much of Heart Rate's `4.6s` processing is the legacy compact archive rebuild versus other processing. |
599 601
 
600 602
 ## Current Diagnosis
601 603
 
@@ -729,6 +731,14 @@ The likely bottleneck is per-row SQLite work:
729 731
   handful of events. The next query shape starts from
730 732
   `sample_observation_events(observation_id, event_kind)` and joins to samples
731 733
   for type filtering.
734
+- The `e7d45a2` follow-up report validated the event-count query shape:
735
+  `SummedFinalizeEventCountElapsed` dropped to `0.0s` and finalization is no
736
+  longer the active repeated-capture bottleneck.
737
+- The active repeated-capture bottleneck is now processing, specifically the
738
+  legacy compact record archive/hash path for changed high-volume metrics. The
739
+  latest report spent `9.1s` in processing, including Heart Rate `4.6s` for
740
+  only `18` delta events. The next diagnostic split must quantify compact
741
+  archive rebuild directly before replacing it with a SQLite-derived state path.
732 742
 - A large older-build first import on an `8.4M`-record database completed but
733 743
   took `166m10s`, with `137m31s` summed insert time. This confirms that full
734 744
   authorized backup volume can be much larger than the original 15-type test
@@ -792,10 +802,12 @@ Prioritize experiments in this order:
792 802
    identity unless the build provenance is otherwise certain. `sourceCommit`
793 803
    and `sourceDirty` are useful when present, but may be `unknown` for normal
794 804
    Xcode test installs.
795
-8. Run a repeated full-profile capture after counting observation events from
796
-   the event table first. Compare `SummedFinalizeEventCountElapsed` and per-type
797
-   event-count time against the post-`bf5a861` overnight baseline: `2.5s` total,
798
-   Heart Rate `0.9s`, and Cycling Distance `0.7s`.
805
+8. Run a repeated full-profile capture after processing subphase diagnostics.
806
+   Compare `SummedProcessingRecordArchiveRebuildElapsed`,
807
+   `SummedProcessingDeltaApplyElapsed`,
808
+   `SummedProcessingRecordArchiveFinalizeElapsed`, and per-type values against
809
+   the `e7d45a2` processing baseline: `9.1s` total, Heart Rate `4.6s`, Active
810
+   Energy `1.8s`, Basal Energy `1.5s`.
799 811
 9. Keep watching first-import insert timing on the next clean large-database
800 812
    import because the new `sample_versions(start_date, sample_id)` index from
801 813
    `bf5a861` is a write-path tradeoff.
+26 -6
HealthProbe/Services/HealthKitService.swift
@@ -1207,7 +1207,9 @@ final class HealthKitService {
1207 1207
             let firstPageApplyStartedAt = Date()
1208 1208
             deltaPages.append(firstDeltaPage)
1209 1209
             estimatedRecordCount += firstDeltaPage.samples.count - firstDeltaPage.deletedObjects.count
1210
-            captureTimings.processingElapsedSeconds += Date().timeIntervalSince(firstPageApplyStartedAt)
1210
+            let deltaApplyElapsed = Date().timeIntervalSince(firstPageApplyStartedAt)
1211
+            captureTimings.processingElapsedSeconds += deltaApplyElapsed
1212
+            captureTimings.processingDeltaApplyElapsedSeconds += deltaApplyElapsed
1211 1213
             processedEventCount += pageEventCount(firstDeltaPage)
1212 1214
             shouldFetchNextPage = firstDeltaPage.samples.count + firstDeltaPage.deletedObjects.count >= incrementalStrategy.queryPageLimit
1213 1215
             progress?.updateBlockProgress(
@@ -1272,7 +1274,9 @@ final class HealthKitService {
1272 1274
             let applyStartedAt = Date()
1273 1275
             deltaPages.append(page)
1274 1276
             estimatedRecordCount += page.samples.count - page.deletedObjects.count
1275
-            captureTimings.processingElapsedSeconds += Date().timeIntervalSince(applyStartedAt)
1277
+            let deltaApplyElapsed = Date().timeIntervalSince(applyStartedAt)
1278
+            captureTimings.processingElapsedSeconds += deltaApplyElapsed
1279
+            captureTimings.processingDeltaApplyElapsedSeconds += deltaApplyElapsed
1276 1280
             processedEventCount += pageEventCount(page)
1277 1281
             shouldFetchNextPage = page.samples.count + page.deletedObjects.count >= incrementalStrategy.queryPageLimit
1278 1282
             progress?.updateBlockProgress(
@@ -1298,7 +1302,9 @@ final class HealthKitService {
1298 1302
             sampleType: sampleType,
1299 1303
             deltaPages: deltaPages
1300 1304
         )
1301
-        captureTimings.processingElapsedSeconds += Date().timeIntervalSince(archiveRebuildStartedAt)
1305
+        let archiveRebuildElapsed = Date().timeIntervalSince(archiveRebuildStartedAt)
1306
+        captureTimings.processingElapsedSeconds += archiveRebuildElapsed
1307
+        captureTimings.processingRecordArchiveRebuildElapsedSeconds += archiveRebuildElapsed
1302 1308
 
1303 1309
         captureTimings.addFinalization(try await finalizeArchiveVerification(
1304 1310
             sampleType: sampleType,
@@ -1544,7 +1550,9 @@ final class HealthKitService {
1544 1550
                     recordCount += 1
1545 1551
                 }
1546 1552
             }
1547
-            captureTimings.processingElapsedSeconds += Date().timeIntervalSince(processStartedAt)
1553
+            let recordProcessingElapsed = Date().timeIntervalSince(processStartedAt)
1554
+            captureTimings.processingElapsedSeconds += recordProcessingElapsed
1555
+            captureTimings.processingInitialRecordElapsedSeconds += recordProcessingElapsed
1548 1556
 
1549 1557
             processedEventCount += pageEventCount(page)
1550 1558
             shouldFetchNextPage = page.samples.count + page.deletedObjects.count >= importStrategy.queryPageLimit
@@ -1571,7 +1579,9 @@ final class HealthKitService {
1571 1579
 
1572 1580
         let finalizeHashStartedAt = Date()
1573 1581
         let contentHash = hashBuilder.finalize()
1574
-        captureTimings.processingElapsedSeconds += Date().timeIntervalSince(finalizeHashStartedAt)
1582
+        let hashFinalizeElapsed = Date().timeIntervalSince(finalizeHashStartedAt)
1583
+        captureTimings.processingElapsedSeconds += hashFinalizeElapsed
1584
+        captureTimings.processingRecordArchiveFinalizeElapsedSeconds += hashFinalizeElapsed
1575 1585
         progress?.updateBlockProgress(
1576 1586
             typeIdentifier,
1577 1587
             detail: pageNumber == 1 ? "Imported 1 page" : "Imported \(pageNumber) pages",
@@ -1613,7 +1623,9 @@ final class HealthKitService {
1613 1623
 
1614 1624
         let archiveFinalizeStartedAt = Date()
1615 1625
         let recordArchiveData = archiveWriter.finalize()
1616
-        captureTimings.processingElapsedSeconds += Date().timeIntervalSince(archiveFinalizeStartedAt)
1626
+        let archiveFinalizeElapsed = Date().timeIntervalSince(archiveFinalizeStartedAt)
1627
+        captureTimings.processingElapsedSeconds += archiveFinalizeElapsed
1628
+        captureTimings.processingRecordArchiveFinalizeElapsedSeconds += archiveFinalizeElapsed
1617 1629
 
1618 1630
         return SampleDistribution(
1619 1631
             totalCount: recordCount,
@@ -2962,6 +2974,10 @@ struct DistributionPageArchiveResult: Equatable {
2962 2974
 private struct DistributionCaptureTimings: Sendable, Equatable {
2963 2975
     var fetchElapsedSeconds: TimeInterval = 0
2964 2976
     var processingElapsedSeconds: TimeInterval = 0
2977
+    var processingDeltaApplyElapsedSeconds: TimeInterval = 0
2978
+    var processingRecordArchiveRebuildElapsedSeconds: TimeInterval = 0
2979
+    var processingInitialRecordElapsedSeconds: TimeInterval = 0
2980
+    var processingRecordArchiveFinalizeElapsedSeconds: TimeInterval = 0
2965 2981
     var insertElapsedSeconds: TimeInterval = 0
2966 2982
     var finalizeElapsedSeconds: TimeInterval = 0
2967 2983
     var finalizeEventCountElapsedSeconds: TimeInterval = 0
@@ -2997,6 +3013,10 @@ private struct DistributionCaptureTimings: Sendable, Equatable {
2997 3013
         ImportTimingBreakdown(
2998 3014
             fetchElapsedSeconds: fetchElapsedSeconds,
2999 3015
             processingElapsedSeconds: processingElapsedSeconds,
3016
+            processingDeltaApplyElapsedSeconds: processingDeltaApplyElapsedSeconds,
3017
+            processingRecordArchiveRebuildElapsedSeconds: processingRecordArchiveRebuildElapsedSeconds,
3018
+            processingInitialRecordElapsedSeconds: processingInitialRecordElapsedSeconds,
3019
+            processingRecordArchiveFinalizeElapsedSeconds: processingRecordArchiveFinalizeElapsedSeconds,
3000 3020
             insertElapsedSeconds: insertElapsedSeconds,
3001 3021
             finalizeElapsedSeconds: finalizeElapsedSeconds,
3002 3022
             finalizeEventCountElapsedSeconds: finalizeEventCountElapsedSeconds,
+19 -0
HealthProbe/Utilities/SnapshotFetchProgress.swift
@@ -3,6 +3,10 @@ import Foundation
3 3
 struct ImportTimingBreakdown: Sendable, Equatable {
4 4
     var fetchElapsedSeconds: TimeInterval = 0
5 5
     var processingElapsedSeconds: TimeInterval = 0
6
+    var processingDeltaApplyElapsedSeconds: TimeInterval = 0
7
+    var processingRecordArchiveRebuildElapsedSeconds: TimeInterval = 0
8
+    var processingInitialRecordElapsedSeconds: TimeInterval = 0
9
+    var processingRecordArchiveFinalizeElapsedSeconds: TimeInterval = 0
6 10
     var insertElapsedSeconds: TimeInterval = 0
7 11
     var finalizeElapsedSeconds: TimeInterval = 0
8 12
     var finalizeEventCountElapsedSeconds: TimeInterval = 0
@@ -23,6 +27,17 @@ struct ImportTimingBreakdown: Sendable, Equatable {
23 27
         fetchElapsedSeconds + processingElapsedSeconds + insertElapsedSeconds + finalizeElapsedSeconds
24 28
     }
25 29
 
30
+    var processingAccountedElapsedSeconds: TimeInterval {
31
+        processingDeltaApplyElapsedSeconds
32
+        + processingRecordArchiveRebuildElapsedSeconds
33
+        + processingInitialRecordElapsedSeconds
34
+        + processingRecordArchiveFinalizeElapsedSeconds
35
+    }
36
+
37
+    var processingOtherElapsedSeconds: TimeInterval {
38
+        max(0, processingElapsedSeconds - processingAccountedElapsedSeconds)
39
+    }
40
+
26 41
     var finalizeAccountedElapsedSeconds: TimeInterval {
27 42
         finalizeEventCountElapsedSeconds
28 43
         + finalizeTypeSummaryElapsedSeconds
@@ -176,6 +191,10 @@ final class SnapshotFetchProgress {
176 191
             var combined = partial
177 192
             combined.fetchElapsedSeconds += type.timingBreakdown.fetchElapsedSeconds
178 193
             combined.processingElapsedSeconds += type.timingBreakdown.processingElapsedSeconds
194
+            combined.processingDeltaApplyElapsedSeconds += type.timingBreakdown.processingDeltaApplyElapsedSeconds
195
+            combined.processingRecordArchiveRebuildElapsedSeconds += type.timingBreakdown.processingRecordArchiveRebuildElapsedSeconds
196
+            combined.processingInitialRecordElapsedSeconds += type.timingBreakdown.processingInitialRecordElapsedSeconds
197
+            combined.processingRecordArchiveFinalizeElapsedSeconds += type.timingBreakdown.processingRecordArchiveFinalizeElapsedSeconds
179 198
             combined.insertElapsedSeconds += type.timingBreakdown.insertElapsedSeconds
180 199
             combined.finalizeElapsedSeconds += type.timingBreakdown.finalizeElapsedSeconds
181 200
             combined.finalizeEventCountElapsedSeconds += type.timingBreakdown.finalizeEventCountElapsedSeconds
+14 -0
HealthProbe/Views/Dashboard/DashboardView.swift
@@ -392,6 +392,13 @@ struct DashboardView: View {
392 392
         lines.append("SummedMetricTotalElapsed: \(formatDuration(summedMetricTotalElapsed))")
393 393
         lines.append("SummedFetchElapsed: \(formatDuration(aggregateTiming.fetchElapsedSeconds))")
394 394
         lines.append("SummedProcessingElapsed: \(formatDuration(aggregateTiming.processingElapsedSeconds))")
395
+        if aggregateTiming.processingAccountedElapsedSeconds > 0 {
396
+            lines.append("SummedProcessingDeltaApplyElapsed: \(formatDuration(aggregateTiming.processingDeltaApplyElapsedSeconds))")
397
+            lines.append("SummedProcessingRecordArchiveRebuildElapsed: \(formatDuration(aggregateTiming.processingRecordArchiveRebuildElapsedSeconds))")
398
+            lines.append("SummedProcessingInitialRecordElapsed: \(formatDuration(aggregateTiming.processingInitialRecordElapsedSeconds))")
399
+            lines.append("SummedProcessingRecordArchiveFinalizeElapsed: \(formatDuration(aggregateTiming.processingRecordArchiveFinalizeElapsedSeconds))")
400
+            lines.append("SummedProcessingOtherElapsed: \(formatDuration(aggregateTiming.processingOtherElapsedSeconds))")
401
+        }
395 402
         lines.append("SummedInsertElapsed: \(formatDuration(aggregateTiming.insertElapsedSeconds))")
396 403
         lines.append("SummedFinalizeElapsed: \(formatDuration(aggregateTiming.finalizeElapsedSeconds))")
397 404
         if aggregateTiming.finalizeAccountedElapsedSeconds > 0 {
@@ -454,6 +461,13 @@ struct DashboardView: View {
454 461
             lines.append("  totalElapsed: \(formatDuration(type.totalElapsedSeconds))")
455 462
             lines.append("  fetchElapsed: \(formatDuration(type.timingBreakdown.fetchElapsedSeconds))")
456 463
             lines.append("  processingElapsed: \(formatDuration(type.timingBreakdown.processingElapsedSeconds))")
464
+            if type.timingBreakdown.processingAccountedElapsedSeconds > 0 {
465
+                lines.append("  processingDeltaApplyElapsed: \(formatDuration(type.timingBreakdown.processingDeltaApplyElapsedSeconds))")
466
+                lines.append("  processingRecordArchiveRebuildElapsed: \(formatDuration(type.timingBreakdown.processingRecordArchiveRebuildElapsedSeconds))")
467
+                lines.append("  processingInitialRecordElapsed: \(formatDuration(type.timingBreakdown.processingInitialRecordElapsedSeconds))")
468
+                lines.append("  processingRecordArchiveFinalizeElapsed: \(formatDuration(type.timingBreakdown.processingRecordArchiveFinalizeElapsedSeconds))")
469
+                lines.append("  processingOtherElapsed: \(formatDuration(type.timingBreakdown.processingOtherElapsedSeconds))")
470
+            }
457 471
             lines.append("  insertElapsed: \(formatDuration(type.timingBreakdown.insertElapsedSeconds))")
458 472
             lines.append("  finalizeElapsed: \(formatDuration(type.timingBreakdown.finalizeElapsedSeconds))")
459 473
             if type.timingBreakdown.finalizeAccountedElapsedSeconds > 0 {