Skip to content

Commit e19dffb

Browse files
Vincent Herbstclaude
andcommitted
diag(io): measure the engine with a reader that allocates nothing
AE#445 round 2 (cmcpherson274, tvOS 26.6): the reporter re-ran the 30-minute hold against main with the bridge pool verified present and his footprint did not move. Slope still 1.77 MB/s, still the source mux rate, still a silent jetsam kill. His reader preads straight into the buffer the bridge hands it and allocates nothing per read, so the pool had nothing to drain on his stack and could never have moved that line. Round 1 measured the harness. customio --live read its spool with FileHandle.readData, which strands one autoreleased Data per read on exactly the thread the fix was about, so ratio 1.00 before the pool and 0.00 after were the harness's own retention wearing his signature. The control that was missing is an arm that allocates nothing: it would have been flat BEFORE the fix too, which is the reading that never happened. So the POSIX arm becomes the default (--foundation-reader keeps the allocating one as the control that proves the pool drains), and it is flat: 541 s at 14 Mbit/s physFP 65 -> 41 MB retention ratio -0.03 180 s, 300 s DVR physFP 79 -> 80 MB retention ratio 0.00 across 900 MB of source. The engine retains nothing when the host reader does not. The harness also states how far behind the live edge the engine ever reaches back, because that is the figure a live host sizes its ring by. It is 0.0 MB over 1 seek in both arms, DVR window included: the timeshift lives in the segment cache on disk, not in the source, so a ring that keeps history keeps it for a request that never arrives. That leaves the question the instrument could not answer. Three rounds ended on "phys_footprint climbs, every itemized bucket is flat", and that stayed true because the buckets are either totals (vmInt/vmExt/vmCmp) or heap-only (mallocBlocks and the size-class census). Nothing named a region outside malloc, and his own block arithmetic points there: the byte slope holds at the mux rate while the block rate falls from 23/s to 2.6/s across his series, so what still strands is not one allocation per read. VMRegionCensus walks the task's VM map with vm_region_recurse_64 and tallies dirty plus swapped pages per user_tag, skipping file-backed dirt because it belongs to the file. It reports GROWTH rather than a total, and that choice is measured rather than stylistic: even the anonymous total overshoots phys_footprint (100 MB against 56 MB) because IOSurface and video-bitstream mappings read as anonymous here while the kernel charges them to whoever created them. A total that cannot be checked against the line beside it is worse than none; summed positive deltas can be held against the rise in physFP over the same span. From a live session: vmGrewMB=31 vmRegions=358 vmTagTop=IOSURFACE_ALT:+28MB(66),MALLOC_SMALL:+2MB(27) It rides the existing setLargeAllocationCensusEnabled switch, so a reporter needs no new call, and the first tick anchors the baseline itself so the load burst is part of the anchor rather than part of the finding. Tests: 2258 pass. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01WbciAqCSxpaiUpTumrCuA9
1 parent 661d079 commit e19dffb

7 files changed

Lines changed: 433 additions & 24 deletions

File tree

Sources/AetherEngine/AetherEngine+Diagnostics.swift

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,11 @@ extension AetherEngine {
2323
triggerPollHz: Double = 8
2424
) {
2525
MallocBlockCensus.isEnabled = enabled
26+
// AE#445: the same switch, because they answer halves of one question. The malloc census
27+
// covers the heap; the region census covers everything phys_footprint counts that malloc
28+
// never sees, which is where three rounds of that issue ran out of instrument.
29+
VMRegionCensus.isEnabled = enabled
30+
if !enabled { VMRegionCensus.clearBaseline() }
2631
if enabled {
2732
MallocBlockCensus.startTriggerWatch(thresholdMB: triggerThresholdMB, pollHz: triggerPollHz)
2833
} else {
@@ -171,6 +176,11 @@ extension AetherEngine {
171176
// 30 s cadence never sampled.
172177
+ MallocBlockCensus.probeFragment()
173178
+ (MallocBlockCensus.isEnabled ? "peakMB=\(MallocBlockCensus.peakSizeInUseMB) " : "")
179+
// AE#445: which VM region the footprint grew in, by tag and by delta against
180+
// the first tick. `physFP` rising while every bucket above it is flat is the
181+
// state this issue kept ending in, and it means the growth is somewhere none of
182+
// them look, not that there is nothing to find.
183+
+ VMRegionCensus.probeFragment()
174184
+ "avioFetchedMB=\(avioMB) "
175185
// #243: only the disc pull path fills this, and only then is it printed. On a
176186
// remote ISO every reader fork pulls through HTTPDiscIOReader, which
Lines changed: 188 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,188 @@
1+
import Foundation
2+
import Darwin.Mach
3+
4+
/// AE#445: names the VM region a rising `phys_footprint` is rising in.
5+
///
6+
/// The 30 s memprobe already carries `vmInt/vmExt/vmCmp/vmIOS` and a malloc census, and three
7+
/// rounds of AE#445 still ended in the same sentence: footprint climbs at the source mux rate,
8+
/// every itemized bucket is flat. Those buckets are totals or heap-only, so retention that lives
9+
/// outside malloc (a CoreMedia pool, an IOSurface, an anonymous `vm_allocate`, a mapped file kept
10+
/// dirty) is invisible to all of them at once. That is not a gap in the theory, it is a gap in the
11+
/// instrument: a slope with no name attached cannot aim the next dig.
12+
///
13+
/// This walks the task's own VM map and tallies DIRTY plus SWAPPED pages per `user_tag`. A tag is
14+
/// not a call site, but it is the difference between "something grew by 428 MB" and "CM_MEMORYPOOL
15+
/// grew by 428 MB", which is one subsystem instead of a process.
16+
///
17+
/// **What it reports is GROWTH, not a total, because only growth is calibrated.** Dirty pages of a
18+
/// mapped file belong to the file rather than to the process, so they are skipped; but even the
19+
/// anonymous total still overshoots `phys_footprint` (measured: 100 MB against 56 MB), because
20+
/// IOSurface and video-bitstream mappings look anonymous in this map while the kernel charges them
21+
/// to whoever created them, usually the media server. An absolute total that cannot be checked
22+
/// against the line beside it is worse than none, so the fragment states `vmGrewMB`, the summed
23+
/// POSITIVE deltas since the baseline. That figure has a meaning a reader can verify: hold it
24+
/// against the rise in `physFP` over the same span, and the gap is the part no tag explains.
25+
///
26+
/// Opt-in for the same reason the malloc census is: the walk is O(regions) and takes the map lock.
27+
enum VMRegionCensus {
28+
29+
/// Diagnostic opt-in, set through `AetherEngine.setLargeAllocationCensusEnabled`.
30+
nonisolated(unsafe) static var isEnabled = false
31+
32+
/// tag -> footprint bytes at the moment `markBaseline` ran. Deltas are measured against this,
33+
/// because the absolute figure is dominated by whatever the process was already holding.
34+
nonisolated(unsafe) private static var baseline: [Int: Int]?
35+
private static let lock = NSLock()
36+
37+
struct Tally: Sendable {
38+
let tag: Int
39+
/// Anonymous dirty + swapped bytes, i.e. what this tag contributes to `phys_footprint`.
40+
let footprintBytes: Int
41+
/// Growth since the baseline, 0 when no baseline was taken.
42+
let deltaBytes: Int
43+
var name: String { VMRegionCensus.tagName(tag) }
44+
}
45+
46+
struct Result: Sendable {
47+
var totalFootprintBytes: Int
48+
var regionCount: Int
49+
/// Descending by `footprintBytes`.
50+
var tallies: [Tally]
51+
}
52+
53+
/// Anchor deltas here. Called once a session is actually running, so the load burst is part of
54+
/// the baseline rather than part of the finding.
55+
static func markBaseline() {
56+
guard isEnabled, let snapshot = walk() else { return }
57+
lock.lock()
58+
baseline = snapshot.reduce(into: [Int: Int]()) { $0[$1.key] = $1.value }
59+
lock.unlock()
60+
}
61+
62+
static func clearBaseline() {
63+
lock.lock(); baseline = nil; lock.unlock()
64+
}
65+
66+
static func census() -> Result? {
67+
guard isEnabled, let tags = walk() else { return nil }
68+
lock.lock()
69+
let base = baseline
70+
lock.unlock()
71+
72+
var total = 0
73+
var tallies: [Tally] = []
74+
tallies.reserveCapacity(tags.count)
75+
for (tag, bytes) in tags {
76+
total += bytes
77+
tallies.append(Tally(tag: tag,
78+
footprintBytes: bytes,
79+
deltaBytes: base.map { bytes - ($0[tag] ?? 0) } ?? 0))
80+
}
81+
tallies.sort { $0.footprintBytes > $1.footprintBytes }
82+
return Result(totalFootprintBytes: total, regionCount: regionCount, tallies: tallies)
83+
}
84+
85+
/// One memprobe fragment. Ordered by DELTA rather than by size, because the tag holding the most
86+
/// is almost always the same one every session and says nothing; the tag that grew is the finding.
87+
/// The first fragment of a session doubles as the baseline, so a reporter gets deltas without
88+
/// having to know there is a baseline to take. That makes the load burst part of the anchor
89+
/// rather than part of the finding, which is what the anchor is for.
90+
static func probeFragment(top: Int = 3) -> String {
91+
guard let result = census() else { return "" }
92+
lock.lock()
93+
if baseline == nil {
94+
baseline = result.tallies.reduce(into: [Int: Int]()) { $0[$1.tag] = $1.footprintBytes }
95+
}
96+
lock.unlock()
97+
let ranked = result.tallies.sorted { $0.deltaBytes > $1.deltaBytes }.prefix(top)
98+
let listed = ranked
99+
.filter { $0.footprintBytes >= 1 << 20 }
100+
.map { "\($0.name):\($0.deltaBytes >= 0 ? "+" : "")\($0.deltaBytes >> 20)MB(\($0.footprintBytes >> 20))" }
101+
.joined(separator: ",")
102+
let grown = result.tallies.reduce(0) { $0 + max(0, $1.deltaBytes) }
103+
return "vmGrewMB=\(grown >> 20) vmRegions=\(result.regionCount) "
104+
+ "vmTagTop=\(listed.isEmpty ? "none" : listed) "
105+
}
106+
107+
// MARK: - Walk
108+
109+
nonisolated(unsafe) private static var regionCount = 0
110+
111+
/// `pages_dirtied` counts kernel pages, so the multiplier has to be the kernel's, not a constant.
112+
private static let pageSizeBytes = Int(sysconf(_SC_PAGESIZE))
113+
114+
/// tag -> dirty + swapped bytes. `vm_region_recurse_64` rather than `mach_vm_region_recurse`:
115+
/// the mach_vm entry points are not in the public tvOS/iOS SDK, and on a 64-bit target the
116+
/// vm_ variants carry the same widths.
117+
private static func walk() -> [Int: Int]? {
118+
var tags: [Int: Int] = [:]
119+
var address: vm_address_t = 0
120+
var depth: UInt32 = 0
121+
var regions = 0
122+
let pageSize = Self.pageSizeBytes
123+
124+
while true {
125+
var size: vm_size_t = 0
126+
var info = vm_region_submap_info_data_64_t()
127+
var count = mach_msg_type_number_t(
128+
MemoryLayout<vm_region_submap_info_data_64_t>.size / MemoryLayout<Int32>.size
129+
)
130+
let kr = withUnsafeMutablePointer(to: &info) { infoPtr in
131+
infoPtr.withMemoryRebound(to: Int32.self, capacity: Int(count)) { intPtr in
132+
vm_region_recurse_64(mach_task_self_, &address, &size, &depth, intPtr, &count)
133+
}
134+
}
135+
guard kr == KERN_SUCCESS else { break }
136+
137+
// A submap is a container, not a mapping: descend rather than tally, or its children
138+
// are counted once as themselves and once inside their parent.
139+
if info.is_submap != 0 {
140+
depth += 1
141+
continue
142+
}
143+
144+
regions += 1
145+
// File-backed dirt is the file's, not the process's: including it inflates the total
146+
// past the `phys_footprint` it exists to explain.
147+
if info.external_pager == 0 {
148+
let footprint = (Int(info.pages_dirtied) + Int(info.pages_swapped_out)) * pageSize
149+
if footprint > 0 {
150+
tags[Int(info.user_tag), default: 0] += footprint
151+
}
152+
}
153+
154+
let next = address.addingReportingOverflow(vm_address_t(size))
155+
if next.overflow || size == 0 { break }
156+
address = next.partialValue
157+
}
158+
159+
guard regions > 0 else { return nil }
160+
regionCount = regions
161+
return tags
162+
}
163+
164+
// MARK: - Tag names
165+
166+
/// The subset worth naming for a playback process. Anything else prints its number, which is
167+
/// still enough to look up in `<mach/vm_statistics.h>` or to compare across two runs.
168+
private static let names: [Int: String] = [
169+
0: "UNTAGGED", 1: "MALLOC", 2: "MALLOC_SMALL", 3: "MALLOC_LARGE", 4: "MALLOC_HUGE",
170+
5: "SBRK", 6: "REALLOC", 7: "MALLOC_TINY", 8: "MALLOC_LARGE_REUSABLE",
171+
9: "MALLOC_LARGE_REUSED", 10: "ANALYSIS_TOOL", 11: "MALLOC_NANO", 12: "MALLOC_MEDIUM",
172+
20: "MACH_MSG", 21: "IOKIT", 30: "STACK", 31: "GUARD", 32: "SHARED_PMAP", 33: "DYLIB",
173+
34: "OBJC_DISPATCHERS", 35: "UNSHARED_PMAP", 40: "APPKIT", 41: "FOUNDATION",
174+
42: "COREGRAPHICS", 43: "CORESERVICES", 45: "COREDATA", 50: "ATS", 51: "LAYERKIT",
175+
52: "CGIMAGE", 53: "TCMALLOC", 54: "COREGRAPHICS_DATA", 55: "COREGRAPHICS_SHARED",
176+
56: "COREGRAPHICS_FRAMEBUFFERS", 57: "COREGRAPHICS_BACKINGSTORES", 60: "DYLD",
177+
61: "DYLD_MALLOC", 62: "SQLITE", 63: "JAVASCRIPT_CORE", 66: "GLSL", 67: "OPENCL",
178+
69: "COREIMAGE", 71: "IMAGEIO", 73: "ASSETSD", 74: "OS_ALLOC_ONCE", 75: "LIBDISPATCH",
179+
76: "ACCELERATE", 77: "COREUI", 79: "GENEALOGY", 82: "SWIFT_RUNTIME", 83: "SWIFT_METADATA",
180+
84: "DHMM", 86: "SCENEKIT", 87: "SKYWALK", 88: "IOSURFACE_ALT", 91: "IOSURFACE",
181+
92: "LIBNETWORK", 93: "AUDIO", 94: "VIDEOBITSTREAM", 95: "CM_XPC", 96: "CM_RPC",
182+
97: "CM_MEMORYPOOL", 98: "CM_READCACHE", 99: "CM_CRABS", 100: "QUICKLOOK"
183+
]
184+
185+
static func tagName(_ tag: Int) -> String {
186+
names[tag] ?? "tag\(tag)"
187+
}
188+
}

0 commit comments

Comments
 (0)