Audience: operator with shell access to a Windows box that has the
target dataset loaded under the daemon (the 7-drive reference box, or
any equivalent machine with at least 4 indexed NTFS volumes).
Source-of-truth tracker: the live progress doc lives in
docs/refactor/memory-tiering-implementation-plan.md (gitignored —
local working copy on the implementer's machine). Use this runbook
when you want the what to run on Windows without the
implementation-side context.
Companion docs (added 2026-05-05 alongside the v0.6.0 readiness pass):
memory-tiering-readiness-validation-2026-05-05.md— dual-platform capture of the Phase 8 + 9 operator-surface readiness pass (150 / 150 scenarios on Mac and Windows). This is the canonical validation evidence for the v0.6.0 cut.memory-tiering-bake-criteria.md— operationalised exit criteria for the one-weekmainbake that precedes the v0.6.0 cut.
Section map:
- §1 — Phase 5 operator gates (G1-G4), ~75 min wall-clock total.
- §2 — Phase 6 24-h
min_tier = "Warm"operator soak. - §3 — Phase 7 24-h USN-journal continuous-churn operator soak.
- §4 — Phase 8 operator-command gates (G5-G8), ~20 min wall-clock total.
- §5 — PR-attachment checklist for the acceptance PR.
- §6 — Reference captures from the 2026-05-02 v0.5.86 baseline run.
For the long-running §2 + §3 soaks, the operator-friendly entry point is
the just soak recipe (see
scripts/dev/long-soak.rs and
just/dev.just), which automates the daemon
lifecycle, hourly snapshots, and the end-of-soak grep validators that
close each gate.
Cross-reference convention. External code / docs that point INTO this runbook should reference gate IDs (
G1,G6,Phase 6 soak, etc.) — never raw section numbers (§3,§5). Section numbers renumber when new sections land (Phase 7 added 2026-05-05 forced one such renumbering). Gate IDs are stable for the life of the gate. When inserting a new section here, search the workspace for§references that point at this file before bumping any number — and prefer rewriting them to anchor / gate-ID style on the way through.
- Windows 10 1709+ or Windows 11 (the
MEMORY_RESOURCE_NOTIFICATIONAPI has been stable since 1709; older Windows editions degrade to the never-fires path documented incrate::cache::pressure). - The daemon binary built from the branch under test, copied to the
host (or built locally with
cargo build --release -p uffs-daemon). - The seven NTFS volumes loaded against the daemon — confirm with the
Phase-8-E per-drive tier table:
uffs --daemon status # expect: Status: Ready uffs --daemon status_drives
daemon status_drivesis the canonical post-Phase-8 view: a fixed- width table withDRIVE / TIER / RESIDENT / QPM / LAST QUERY (ms) / PIN UNTIL (ms)columns, sorted ASCII ascending by drive letter. Expect every drive'sTIERcolumn to bewarm(default after load) — anyparked/coldfrom the start means the gate setup is wrong; bounce the daemon (uffs --daemon stop→uffs --daemon start --drives C,D,E,F,G,M,S). - Task Manager → Details tab → enable the I/O priority column
via column-header → Select columns… → check
I/O priority. This is required for gate G3 (USN catch-up I/O priority capture). - PowerShell 5.1 or PowerShell 7 — the snippets below use
Start-Process/Get-Counter/Wait-Eventwhich exist in both.
Duration: ~5 min wall-clock.
Plan reference: docs/refactor/memory-tiering-implementation-plan.md §3 Phase 5 line "Stress test: spawn allocator that drains free RAM."
Open two terminals on the same Windows host. In terminal A start the daemon with structured logging:
$env:RUST_LOG = "uffs_daemon=info,cache.pressure=info,shard.transition=info"
uffs --daemon start --drives C,D,E,F,G,M,S 2>&1 | Tee-Object -FilePath C:\Temp\uffsd-G1.logWait until uffs --status reports Ready for every drive.
In terminal B, allocate memory until the kernel publishes
LowMemoryResourceNotification. The simplest portable driver is a
testlimit64-style PowerShell loop (no separate binary required).
Critical: pages must be touched, not just reserved.
New-Object byte[] 1073741824on its own only commits virtual address space (Private Bytes climbs) but leaves the pages non-resident (Working Set flat), because Windows backs zero-filled pages on first write via the demand-zero handler. The kernel'sLowMemoryResourceNotificationfires on physical-RAM pressure, not commit-charge pressure, so a reserve-only allocator never trips the cascade. Force commit by writing a non-zero byte to every page —[Array]::Fill($arr, [byte]1)is the fastest portable way (CLR-native; fills 1 GiB in milliseconds). If you have Sysinternals installed,testlimit.exe -d 1024 -c Nbypasses .NET entirely and is the canonical tool for this.
# Allocate 1 GiB chunks AND commit by touching every page; auto-break on Low.
$alloc = New-Object System.Collections.Generic.List[byte[]]
try {
while ($true) {
$arr = New-Object byte[] 1073741824
[Array]::Fill($arr, [byte]1) # ← commits every page; the line above only reserves
$alloc.Add($arr)
$free = (Get-Counter '\Memory\Available MBytes').CounterSamples[0].CookedValue
Write-Host ("allocated {0} GiB; free = {1:N0} MiB" -f $alloc.Count, $free)
if ($free -lt 512) {
Write-Host "Low-memory zone reached — holding 10 s for the cascade to drain, then releasing."
Start-Sleep -Seconds 10
break
}
Start-Sleep -Milliseconds 500
}
} finally {
$alloc.Clear()
[GC]::Collect()
Write-Host "released"
}The kernel typically fires LowMemoryResourceNotification once
Available MBytes drops below ~256 MB on a 16 GB box (Windows
auto-tunes the threshold to ~32 MB on the lower end and
PhysicalMemory / 64 on the upper end — see Microsoft Learn's
CreateMemoryResourceNotification).
The daemon log (C:\Temp\uffsd-G1.log) must show (note: tracing
target names like cache.pressure and shard.transition set the
filter routing but are not rendered in the log message text under
the default formatter — grep on the message text and field names
shown below):
INFO Pressure transition observed level=Low
INFO letter=C from=warm to=parked freed_mb=… last_query_at_ms=… reason="pressure-cascade"
INFO letter=G from=warm to=parked freed_mb=… last_query_at_ms=… reason="pressure-cascade"
…
Grep cheat-sheet:
Select-String -Path C:\Temp\uffsd-G1.log -Pattern 'Pressure transition|reason="pressure-cascade"' |
Select-Object -ExpandProperty Line— one cascade line per Warm shard. The letter field's order must
follow oldest-last_query_at_ms-first (LRU contract pinned by
crate::index::tests::lifecycle_hooks::cascade_demote_one_step_picks_lru_warm_and_drains_in_order
pressure_subscriber_drains_warm_cascade_on_low_and_no_ops_on_high).
Format note (G4 follow-up, 2026-05-02): the cascade demote event was previously emitted twice per shard — once from the registry primitive (
reason="demote",letter=field) and a second time fromcascade_demote_one_stepitself (reason= "pressure-cascade",drive=field, with the "Pressure cascade demoted one LRU Warm shard" message text). The second event was redundant and the gap between the two confused log analysis, so the discriminator is now in the registry primitive'sreasonfield directly and the second event is gone. Old runbooks that grepped forPressure cascade demotedwill see zero matches — usereason="pressure-cascade"instead.
When you Ctrl-C the allocator the kernel fires
HighMemoryResourceNotification. The log must show:
INFO Pressure transition observed level=High
— and no further cascade lines after that timestamp.
Duration: ~3 min wall-clock (re-uses the G1 terminal A log). Plan reference: §3 Phase 5 line "Working set drops in Task Manager within 5 s of demote."
Re-run the G1 allocator loop with Task Manager → Details visible.
- Note
uffsd.exeWorking Set (Memory) before the allocator starts (baseline_ws). - Press the kernel into firing
Low(allocator runs). - Within 5 s of the first
shard.transitioncascade line inuffsd-G1.log,uffsd.exeWorking Set must drop belowbaseline_ws / 2(typical observation: 5341 MB → ~1 200 MB on the 7-drive reference box).
Two screenshots in the PR description, both with
Get-Date | Out-Host visible at the top:
- Task Manager → Details showing
uffsd.exeWorkingSetat the peak (just beforeLowfires). - Task Manager → Details showing
uffsd.exeWorkingSet≤ 5 s after the first cascade line.
The drop is caused by the per-batch EmptyWorkingSet call wired in
Phase 5 task 5.4 (crate::index::transitions::IndexManager::demote_idle_shards
→ WorkingSetTrim::trim). Mac/Linux ship a no-op stub.
Duration: ~6 min wall-clock (the USN refresh runs every 5 min by default).
Plan reference: §3 Phase 5 line "During USN catch-up, Task Manager I/O priority on uffsd.exe shows 'Low'."
Force a USN catch-up by reducing the cadence — easier than waiting the default 5 min between ticks. In terminal A:
$env:UFFS_USN_REFRESH_INTERVAL_SECS = "30"
$env:RUST_LOG = "uffs_daemon=info,shard.refresh=info"
uffs --daemon stop
uffs --daemon start --drives C,D,E,F,G,M,S 2>&1 | Tee-Object -FilePath C:\Temp\uffsd-G3.logThe 30-second cadence guarantees a refresh tick within ~1 minute of each Warm shard becoming visible to the controller.
Per-thread, not per-process.
BackgroundIoScopecallsSetThreadPriority(GetCurrentThread(), THREAD_MODE_BACKGROUND_BEGIN)on the calling thread only — specifically, on thetokio::task::spawn_blockingworker that runs the refresh closure for one drive. Windows lowers that thread's I/O priority toIoPriorityVeryLowand memory priority to lowest; scheduling priority is left unchanged at Normal (Base Priority = 8) by design. The process-level I/O priority (the column shown in PE's main window or Task Manager Details) stays Normal, because the daemon's main thread + IPC accept loop are not in background mode. Do not look at the process-row I/O Priority column — it will (correctly) always show Normal.
Three capture paths, in increasing operator effort:
What changes when
THREAD_MODE_BACKGROUND_BEGINfires. The Win32 documentation says "the system lowers the resource scheduling priorities of the thread", but the only properties that actually change in observable Windows APIs are:
- I/O priority — drops from
IoPriorityNormaltoIoPriorityVeryLow. Read viaNtQueryInformationThread(ThreadIoPriority)or PE's I/O Priority column.- Memory priority — drops to
MEMORY_PRIORITY_LOWEST. Read viaGetThreadInformation(ThreadMemoryPriority).The thread's scheduling priority (
GetThreadPriority, theTHREAD_PRIORITY_*enum) stays atTHREAD_PRIORITY_NORMAL/ Base Priority = 8, by design — background mode is meant to deprioritise I/O and memory without slowing CPU work when the system is idle. This means.NET ProcessThread.PriorityLevelandGet-CimInstance Win32_Threadwill NOT show any change during a tick (verified empirically: 60 s of 10 Hz polling across two ticks captured zero threads at lowered scheduling priority). Only the I/O Priority column or theNtQueryInformationThreadsyscall surface the actual change.
(a) Debug-log grep — text-only, definitive (preferred for PR evidence):
Clear the RUST_LOG env var (it overrides --log-level), restart
with --log-level debug, wait 2-3 ticks, then grep for
BackgroundIoPriority. Empty grep = SetThreadPriority succeeded
on every per-drive worker; the wiring + the unit test
(refresh_usn_for_warm_shards_wraps_each_closure_in_background_io_scope)
complete the proof:
uffs --daemon stop
Remove-Item Env:\RUST_LOG -ErrorAction SilentlyContinue
$env:UFFS_USN_REFRESH_INTERVAL_SECS = "30"
uffs --daemon start --log-level debug --log-file C:\Temp\uffsd-G3-debug.log
# Re-warm so refresh has work to do.
uffs "*" --ext rs --drive C --limit 5 > $null
Start-Sleep -Seconds 90
# Empty grep = success (begin() returned Ok on every closure).
"=== BackgroundIoPriority diagnostic (empty = good) ==="
Select-String -Path C:\Temp\uffsd-G3-debug.log -Pattern 'BackgroundIoPriority' |
Select-Object -ExpandProperty Line
# Tick lines confirm the controller fired during the same window.
"=== Tick lines ==="
Select-String -Path C:\Temp\uffsd-G3-debug.log -Pattern 'USN refresh tick' |
Select-Object -ExpandProperty LineIf the BackgroundIoPriority grep prints any begin failed lines,
that's a real bug — file a follow-up issue with the error string and
stop. G3 stays 🟡 in that case.
(b) Process Explorer Threads tab (GUI screenshot, redundant verification):
- Right-click
uffsd.exe→ Properties → Threads tab. - Right-click any column header → Select Columns → Threads sub-tab → enable I/O Priority. (Base Priority is not useful here — it stays at 8 in background mode.)
- During a tick window (between the
USN refresh tick starting count=NandUSN refresh tick complete refreshed=Nlog lines), screenshot. Expect ≥ 1 thread with I/O Priority = Very Low. Outside the tick, all threads showI/O Priority = Normal.
(c) Sysinternals accesschk.exe -p -t <pid> (if installed):
Dumps per-thread info including I/O priority — grep the output for
I/O Priority: VeryLow during a tick window.
What does NOT work for this gate:
Get-CimInstance Win32_Thread— the WMI provider returns NULL forPriorityCurrent/BasePriorityon modern Windows.(Get-Process uffsd).Threads | Where PriorityLevel -in 'Idle', 'Lowest', 'BelowNormal'— reads scheduling priority viaGetThreadPriority, which doesn't change in background mode.- Task Manager "Details" tab I/O Priority column — process-level only; the daemon's main thread is at Normal so this column stays Normal.
Grep the log for the matching tick window:
Select-String -Path C:\Temp\uffsd-G3.log -Pattern 'USN refresh tick' |
Select-Object -ExpandProperty LineThe transition is driven by crate::cache::background_io::BackgroundIoScope
RAII guards wrapped around each per-letter tokio::task::spawn_blocking
closure in crate::index::transitions::IndexManager::refresh_usn_for_warm_shards
(Phase 5 task 5.7). Mac/Linux: no-op (the trait stub returns
Ok(())). Windows: SetThreadPriority(GetCurrentThread(), THREAD_MODE_BACKGROUND_BEGIN) on enter,
THREAD_MODE_BACKGROUND_END on drop.
BackgroundIoScope::begin() failures are logged at debug level
under target shard.refresh and otherwise swallowed. If (b) or
(c) show the threads stuck at Normal priority during a tick,
restart the daemon with RUST_LOG=...,shard.refresh=debug and
grep:
Select-String -Path C:\Temp\uffsd-G3.log -Pattern 'BackgroundIoPriority' |
Select-Object -ExpandProperty LineA non-empty match on begin failed indicates a real bug (e.g., the
process token is missing SeIncreaseBasePriorityPrivilege, or an AV
product is intercepting SetThreadPriority); empty grep + threads
at Normal would mean the scope guard is not actually running.
Preferred (path (a) above): the empty BackgroundIoPriority
grep + populated USN refresh tick grep from a --log-level debug
run. Two short text blocks, no GUI required. This is sufficient
proof because:
- The unit test
refresh_usn_for_warm_shards_wraps_each_closure_in_background_io_scopeincrates/uffs-daemon/src/index/tests/usn_refresh.rsalready pins thatbegin()andend()are called exactly once per Warm shard per refresh tick. - The empty debug grep proves
SetThreadPriorityreturnedOkfor every per-drive worker (the only failure path istracing::debug!targetshard.refreshlineBackgroundIoPriority::begin failed). - The populated tick grep proves the controller fired during the same observation window.
Optional (path (b) above): screenshot of PE Threads tab with the
I/O Priority column showing Very Low on a worker thread
during a tick. Useful if a reviewer wants visual confirmation but
not required for sign-off.
Reset before moving on:
Remove-Item Env:\UFFS_USN_REFRESH_INTERVAL_SECS
uffs --daemon stopDuration: 60 min wall-clock (one operator-attended setup; runs unattended). Plan reference: §3 Phase 5 line "1-hour sustained-pressure test: no OOM."
Run an adaptive allocator continuously for 60 min. The kernel's
LowMemoryResourceNotification threshold scales with physical RAM
(roughly 1.5% of total — ~1 GB on 64 GB hosts, ~512 MB on 32 GB), so
the allocator must drive sysAvailable down to that threshold to fire
Low; the only correct stop condition is "sysAvailable about to hit a
safety floor", not a hardcoded GiB cap based on guessed reserves
(an empirical lesson: a TotalRAM − 26 GiB cap stopped the allocator
at 38 GiB on a 64 GB host with sysAvailable still at 7 GB, never
firing Low). The version below has only one stop condition — the
256 MB safety floor — so it grows as much as the host has headroom
for, then holds at the target while the daemon cascades:
# Set up daemon log routing FIRST (before allocator), in a fresh
# shell so RUST_LOG doesn't carry over from a previous gate.
Remove-Item Env:\RUST_LOG -ErrorAction SilentlyContinue
$env:RUST_LOG = "uffs_daemon=info,cache.pressure=info,shard.transition=info"
uffs --daemon stop
uffs --daemon start --log-file C:\Temp\uffsd-G4.log
# In a second shell, run the adaptive allocator.
$targetAvailMB = 1024 # squeeze sysAvailable down to ~1 GB to fire Low
$safetyAvailMB = 256 # NEVER drop below this — allocator pauses growth
$rng = [System.Security.Cryptography.RandomNumberGenerator]::Create()
$start = Get-Date
$end = $start.AddMinutes(60)
$alloc = New-Object System.Collections.Generic.List[byte[]]
Write-Host "Adaptive allocator (incompressible random fill; safety floor only)."
Write-Host " target=$targetAvailMB MB safety floor=$safetyAvailMB MB"
Write-Host " start=$($start.ToString('HH:mm:ss')) end=$($end.ToString('HH:mm:ss'))"
while ((Get-Date) -lt $end) {
$avail = [math]::Round((Get-Counter '\Memory\Available MBytes').CounterSamples[0].CookedValue)
$action = if ($avail -lt $safetyAvailMB) {
"hold(safety)"
} elseif ($avail -gt $targetAvailMB) {
$arr = New-Object byte[] 1073741824
$rng.GetBytes($arr) # incompressible — defeats Memory Compression
$alloc.Add($arr)
"+1 GiB"
} else {
"hold(target)"
}
Write-Host "$(Get-Date -Format 'HH:mm:ss') $($action.PadRight(13)) alloc=$($alloc.Count) GiB sysAvailable=$avail MB"
Start-Sleep -Seconds 5
}
$alloc.Clear()
[GC]::Collect()
[GC]::WaitForPendingFinalizers()Why cryptographic random bytes, not
[Array]::Fill($arr, [byte]1). Windows 10/11 enables Memory Compression by default: pages with low entropy (uniform fill, mostly-zeros, repetitive patterns) are compressed in-place to a small fraction of their size and held in the Compression Store under the System process. Verified empirically: abyte 1fill on a 64 GB host let the allocator reach 70 GiB held whilesysAvailablestayed at 4-7 GB the whole time — the OS had compressed ~50 GiB into ~10 GiB of physical memory, so kernel-Low never fired.RandomNumberGenerator.GetBytesproduces ~8 bits/byte entropy which the compressor cannot shrink, so each +1 GiB allocation dropssysAvailableby ~1 GiB linearly as expected. The crypto RNG path is slower (~150 MB/s vs ~3 GB/s for the uniform fill) so each chunk takes ~7 s instead of <1 s, but the kernel-Low signal arrives reliably.
State machine (only three states, no GiB cap):
- Climb:
sysAvailable > target→ add 1 GiB of random bytes. - Hold(target):
safety <= sysAvailable <= target→ hold steady. The daemon's cascade runs here; as it frees memory, sysAvailable rises above target and the allocator climbs again, driving the next Low event. - Hold(safety):
sysAvailable < safety→ stop adding. Prevents OOM-killing other apps when the daemon hasn't cascaded fast enough.
The allocator will grow to whatever GiB count is required to push
sysAvailable down to the target on this specific host. With
incompressible fill that's typically (TotalRAM − DaemonRSS − ~6 GB
OS overhead): on a 64 GB box with the daemon at ~16 GiB, expect
the allocator to reach ~42-46 GiB held when sysAvailable first
crosses the target. Each hold(target) window is the daemon's
chance to cascade; each return to +1 GiB is the next Low trigger.
Over 60 min you should see the daemon log emit a
level=Low ... level=High pair every 30-90 s.
Acceptance criteria:
uffsd.exeis still running (Get-Process uffsd | Select Id, WS).- No
OutOfMemoryErrorlines inuffsd-G4.log. - No
paniclines. uffs --status --drivesreturns within 1 s after the soak completes; the per-drive tier markers reflect a coherent state (some[Parked], some[Hot]/[Warm]where the operator drove queries).
Get-Process uffsd | Select Id, WS, PM, NPM, VM, CPU, StartTimeoutput captured at 0 min, 30 min, and 60 min.- The tail of
uffsd-G4.log(last 200 lines) — should show alternatinglevel=Low/level=Hightransitions and no fatal errors.
Distinguishing pressure-cascade from TTL idle-demote. Every demote — whether TTL-driven (
demote_idle_shards) or pressure-driven (cascade_demote_one_step) — flows through the low-levelRegistry::demote_letter_with_reasonprimitive incache/registry.rs, which emits exactly one canonicalINFO-levelshard.transitionevent per shard. The discriminator is in thereasonfield:
reason="demote"— TTL-driven idle demote (theDemoteReason::IdleTtldefault).reason="pressure-cascade"— kernel-Low pressure cascade demote (DemoteReason::PressureCascade, used only bycascade_demote_one_step).Both events also carry
letter,from,to,freed_mb, andlast_query_at_msfields (the latter was promoted from a cascade-only field to a uniform schema during the G4 follow-up refactor). Operator runbooks can therefore count each path independently with a single grep:# Cascade-demote events (the goal during a memory-pressure soak): $cascade = (Select-String -Path C:\Temp\uffsd-G4.log -Pattern 'reason="pressure-cascade"').Count "Cascade-demote events: $cascade" # TRUE TTL-driven idle demotes (should be 0 on a clean G4 run # with `UFFS_WARM_TO_PARKED_IDLE_SECS=3600`): $ttl = (Select-String -Path C:\Temp\uffsd-G4.log -Pattern 'reason="demote"').Count "TTL idle-demote events: $ttl"No pair-match is required — the
reasonfield is authoritative. Pinned incrates/uffs-daemon/src/index/tests/idle_demote.rs::cascade_demote_emits_single_event_with_pressure_cascade_reasonso a future refactor can't reintroduce the prior dual-event pattern.
Duration: 24 h wall-clock (set up and walk away).
Plan reference: docs/refactor/memory-tiering-implementation-plan.md §3 Phase 6 Windows gate.
Write a daemon.toml to the platform-default path
(%LOCALAPPDATA%\uffs\daemon.toml) with min_tier = "Warm" for C::
$cfgPath = "$env:LOCALAPPDATA\uffs\daemon.toml"
@'
[shards.per_drive."C:"]
min_tier = "WARM"
'@ | Set-Content -Encoding UTF8 -Path $cfgPath
uffs --daemon stop
# shard.ttl at TRACE (not DEBUG) is REQUIRED — see the 2026-05-11
# soak findings in §6 ("Reference captures") sub-section §4.5b
# below. The DEBUG `idle-demote` /
# `min-tier-clamp` events only fire when the controller is
# proposing a demote; during the synthetic-load window drive C
# sits in Warm/Hot with `idle_secs ≈ 0`, so only the catch-all
# TRACE-level `below-ttl` event carries the bonused
# `warm_ttl_sec` field that criterion 3 below scrapes for.
$env:RUST_LOG = "uffs_daemon=info,shard.ttl=trace,shard.transition=info"
uffs --daemon start --drives C,D,E,F,G,M,S 2>&1 | Tee-Object -FilePath C:\Temp\uffsd-phase6-soak.logDo nothing for 24 h. No queries against any drive; let the adaptive-TTL ladder drive demotions naturally.
Acceptance criteria (the Phase 6 contract under [shards.per_drive]):
Note on grep patterns: tracing target names (shard.transition,
shard.ttl) are NOT rendered in the log line text under the default
formatter. In addition, two different conventions coexist in the
source:
cache/registry.rsdemote / promote / usn-refresh events (the canonicalshard.transitioninfo events, including the cascade path'sreason="pressure-cascade"after the G4 follow-up refactor) use field nameletter=and lowercase state names (to=parked).index/transitions.rsshard.ttldebug / trace events (idle-demote evaluation diagnostics) andshard.refreshevents (USN refresh tick) use field namedrive=and theTierLevelDebugformatter (to=Parked, capitalized, unquoted).
The patterns below handle both. Future operators: if you change the daemon's tracing fields, update these patterns in the same commit.
-
C never demotes below
Warm. Grep the soak log:Select-String -Path C:\Temp\uffsd-phase6-soak.log -Pattern '(letter|drive)=C\b.*to="?[Pp]arked"?' -List
Expect zero matches. Every
min-tier-clampevent for C is logged at debug-level viashard.ttlwith the descriptive message"Demote target clamped by per-drive min_tier":Select-String -Path C:\Temp\uffsd-phase6-soak.log -Pattern 'Demote target clamped.*drive=C' -Context 0,0 | Select-Object -First 5
-
Other drives demote normally (Warm → Parked at the configured
warm_ttl_base_secs):Select-String -Path C:\Temp\uffsd-phase6-soak.log -Pattern '(letter|drive)=[DEFGMS]\b.*from="?[Ww]arm"?.*to="?[Pp]arked"?' -List
Expect at least one match per drive (D, E, F, G, M, S).
-
Different TTLs for high-rate vs low-rate drives. After the soak, drive a synthetic 5-min load against C, leave the others idle, and grep for the per-drive
warm_ttl_secfield on theshard.ttlevents.warm_ttl_sec(not the olderchosen_ttl_sec) is the right field for the cross-drive comparison: it is the rate-sensitive Warm→Parked edge that exists on every drive's events regardless of current tier, so the target-vs-peers compare is apples-to-apples (the pre-2026-05-07chosen_ttl_seccompare was structurally impossible to pass when drives were in different tiers — seecrate::index::tests::shard_ttl_eventsfor the contract pin):Select-String -Path C:\Temp\uffsd-phase6-soak.log -Pattern 'warm_ttl_sec' | Select-Object -Last 30 -ExpandProperty Line
The C row's
warm_ttl_secduring the synthetic-load window should exceed the peers' by the600·log2(rate)bonus from the §5.2 formula (crate::cache::policy::warm_ttl). Per-tick evidence requiresshard.ttl=traceinRUST_LOG(see the Setup block above, the 2026-05-11 deferral analysis in §6 sub-section §4.5b, and the 2026-05-14 end-to-end closing capture in §6 sub-section §4.5e — C.max_warm_ttl=3 786 s vs peer max=300 s).
Remove-Item $cfgPath
uffs --daemon stopjust soak phase6 (or rust-script scripts/dev/long-soak.rs phase6)
automates the entire setup → soak → end-of-soak load → validation
flow. See §3 just below for the matching Phase 7 recipe — the two
recipes share their snapshot / output-dir / validation-report shape.
Duration: 24 h wall-clock (set up and walk away).
Plan reference:
docs/refactor/memory-tiering-implementation-plan.md
§3 Phase 7 Windows gate.
Validates that the per-shard USN-journal loop
(crates/uffs-daemon/src/cache/journal_loop.rs, PR #117 / activation
PR #118) keeps a Warm shard's body, bloom, and trie in sync with the
live NTFS journal across 24 h of continuous churn — the long-running
Windows-host equivalent of the Mac-side 1048 / 1048 unit test suite.
The just soak phase7 recipe takes care of everything below; the
manual steps are documented for the operator who wants to understand
what the harness is doing or run a slice of it standalone.
# 1. Pick a churn directory under the user profile. Default in
# long-soak.rs. Avoid system-owned paths so the soak can clean
# up after itself without elevation.
$churnDir = "$env:USERPROFILE\uffs-soak\churn"
New-Item -ItemType Directory -Path $churnDir -Force | Out-Null
# 2. Bounce the daemon with the right log filter.
Remove-Item Env:\RUST_LOG -ErrorAction SilentlyContinue
$env:RUST_LOG = "uffs_daemon=info,shard.refresh=info,shard.transition=info,journal_loop=debug"
uffs --daemon stop
uffs --daemon start --drives C,D,E,F,G,M,S \
--log-file "$env:USERPROFILE\uffs_soak\phase7-$(Get-Date -Format yyyyMMdd-HHmmss)\daemon.log"A continuous create / modify / delete loop in $churnDir. The
just soak phase7 recipe spawns a background thread for this; the
portable PowerShell-only equivalent is:
# Run for 24 h, ~5 files / sec.
$end = (Get-Date).AddHours(24)
$counter = 0
while ((Get-Date) -lt $end) {
$path = Join-Path $churnDir "churn-$($counter % 1024).tmp"
"phase7 churn payload $counter" | Set-Content -Path $path
"appended at $(Get-Date -Format o)" | Add-Content -Path $path
if ($counter % 4 -eq 0) { Remove-Item -Path $path -Force -ErrorAction SilentlyContinue }
Start-Sleep -Milliseconds 200
$counter++
}Four acceptance criteria (the Phase 7 contract under
memory-tiering-implementation-plan.md §3 Phase 7 Windows gate):
-
New-item latency ≤ 2 s. Drop a unique probe file in
$churnDir; confirmuffs --daemon status_drivesreturns a non-error response within 2 s of the file'sLastWriteTime. The harness probes once at T+0 and once at T+24h; both must hit the budget. -
Encrypted-cache refresh fired during the soak (≤ 1× / 5 min, ≥ 1× total over 24 h). Grep the daemon log for the literal substring of the
journal_loop::process_tick-emitted save event:Select-String -Path C:\Temp\uffsd-phase7-soak.log ` -Pattern 'compact-cache save' | Select-Object -ExpandProperty Line | Measure-Object
countmust be≥ 1(≥ 1× total). A 24 h soak typically produces 10-30 events depending on the threshold mix.The matching INFO line shape is:
INFO Journal poll: triggered background compact-cache save \ drive=F reason=AgeElapsed cursor=151008The literal
"compact-cache save"substring is pinned bycrate::cache::journal_loop::tests::save_log_message:: compact_cache_save_log_message_pins_string_target_and_levelso a future rename fails CI before reaching a 24-h soak. See the 2026-05-11 finding in §6 sub-section §4.5c for the validator-regex fix history. -
uffsd.exeWorking Set ≤ 1.5× over 24 h. HourlyGet-Process uffsd | Select Id, WS, ...snapshots. Compare the first to the last:$first = Get-Content (Resolve-Path "$soakDir\snapshots\00h-process.json") | ConvertFrom-Json $last = Get-Content (Resolve-Path "$soakDir\snapshots\24h-process.json") | ConvertFrom-Json $ratio = $last.WS / $first.WS "WS ratio: $ratio (must be <= 1.5)"
The harness wraps this assertion as a
validation/*.{pass,fail}breadcrumb.Note (2026-05-13 finding): on Windows the
WSfield drops sharply on the firstEmptyWorkingSettrim (Phase 5 G2 wiring) and stays low for the rest of the soak — the daemon's actual memory footprint isPM(Private Memory Size / commit-charge), which is also in every snapshot. The≤ 1.5×bound still catches a real leak (which would grow both WS and PM monotonically), but reviewers should cross-checkPMfrom00h-process.jsonvs23h-process.jsonfor the leak-relevant reading. See §6 sub-section §4.5d for the full breakdown. -
No
panic/OutOfMemoryError/FATAL. Same grep pattern as G4:Select-String -Path C:\Temp\uffsd-phase7-soak.log ` -Pattern '\bpanic\b|\bOutOfMemoryError\b|\bFATAL\b'
Must return zero matches.
uffs --daemon stop
Remove-Item -Recurse -Force "$env:USERPROFILE\uffs-soak\churn"The one-line invocation that captures all four assertions in a single 24 h run is:
just soak phase7…which writes its full output (daemon log + per-hour snapshots +
validation breadcrumbs + summary) into
$env:USERPROFILE\uffs_soak\phase7-<timestamp>\. Attach
summary.txt + the snapshot dir to the acceptance PR.
For a Mac-side shake-out before burning the real Windows 24 h:
just soak phase7 --dev # 5-min run, 1-min snapshots, relaxed boundsThe --dev flag is documented in the harness CLI; production
invocations omit it.
These gates validate the four operator-driven memory-tiering commands shipped in Phase 8 (PRs #122 + #123). They run against the same daemon used for the Phase 5 / 6 gates — pick any moment when interactive search is paused. Captures go in the same PR description as the Phase 5 / 6 captures.
The four gates correspond 1:1 to plan tasks 8.1 / 8.2 / 8.3 / 8.4. Run them in order — G7 is destructive (deletes a drive's caches) and the order leaves the daemon in a known-good shape for the final G8 render.
Duration: ~3 min wall-clock. Plan reference: plan task 8.1; PR #122.
A daemon running with the seven drives in mixed tiers (any steady state — typically the post-G4 shape after the Phase-5 soak).
# Capture pre-hibernate state.
"=== Pre-hibernate ==="
Get-Process uffsd | Select Id, WS, PM, NPM, VM
uffs --daemon status_drives# Hibernate every loaded drive.
uffs --daemon hibernateExpected stdout (drive letters depend on the registry):
Daemon hibernated 7 drive(s):
Hot -> Cold: C
Warm -> Cold: D, E, F
Parked -> Cold: G, M, S
Already Cold: (none)
"=== Post-hibernate ==="
Get-Process uffsd | Select Id, WS, PM, NPM, VM
uffs --daemon status_drives
# Hibernate keeps the encrypted compact caches on disk — verify
# they're all still there (the *_compact.uffs files are the
# Cold-tier source-of-truth for re-promote).
"=== Cache files preserved ==="
Get-ChildItem "$env:LOCALAPPDATA\uffs\cache\*_compact.uffs" |
Select-Object Name, Length, LastWriteTimeAcceptance criteria:
- Every drive's
TIERcolumn instatus_drivesiscold. uffsd.exeWorking Set drops by ≥ 50 % vs the pre-hibernate sample (no body Arc, no parked-body bloom + trie resident).- Every
<letter>_compact.uffsfile from the pre-hibernate sample is still on disk with the sameLength(hibernate releases RAM only — disk untouched).
Duration: ~10 min wall-clock. Plan reference: plan task 8.2; PR #122.
The pin-contract test that the Mac unit-test suite cannot exercise is "pinned shard survives the live demote-controller's idle-TTL evaluation" — Mac tests inject mock clocks; this gate uses the real wall clock with shortened TTLs so the operator can observe the pin actually defending against demote in the wild.
Continuing from G5 — every drive Cold. Lower the warm-to-parked TTL via env so the demote-controller can prove the pin works without a default-30-min wait:
$env:UFFS_WARM_TO_PARKED_IDLE_SECS = "30"
$env:UFFS_PARKED_TO_COLD_IDLE_SECS = "60"
$env:RUST_LOG = "uffs_daemon=info,shard.transition=info,shard.ttl=debug"
uffs --daemon stop
uffs --daemon start --drives C,D,E,F,G,M,S 2>&1 |
Tee-Object -FilePath C:\Temp\uffsd-G6.log# Pin C in Hot for 5 minutes.
uffs --daemon preload C --pin-minutes 5Expected stdout:
Daemon preloaded (5-min pin):
Promoted to Hot: C
Already Hot: (none)
Pin expires at: <unix-millis> (Unix-millis)
Verify C is Hot + pinned and the others are still Cold:
"=== Pre-wait ==="
uffs --daemon status_drivesWait through 1.5× the warm-to-parked TTL — total ~90 s — long
enough for demote_idle_shards to evaluate every shard at least
twice:
"=== Wait 90 s for the idle-demote controller to fire ==="
Start-Sleep -Seconds 90
"=== Post-wait ==="
uffs --daemon status_drivesConfirm the demote-controller log shows zero to=parked /
to=cold lines for letter=C:
Select-String -Path C:\Temp\uffsd-G6.log -Pattern '(letter|drive)=C\b.*to="?[Pp]arked|cold"?' |
Select-Object -ExpandProperty LineEmpty output = the pin gate in IndexManager::demote_idle_shards
cascade_demote_one_stepcorrectly skipped C.
Paste into the PR:
- Pre-wait
status_drivesrow for C —tier=hot,pin_until_ms > 0. - Post-wait
status_drivesrow for C — stilltier=hotdespite 90 s past the warm-to-parked TTL. - Empty grep result above (verbatim).
Acceptance criteria:
- C's
TIERcolumn stayshotfor the full 90-s window. - C's
PIN UNTIL (ms)column is non-zero and at least 5 min in the future. - No
letter=Cto=parked/to=coldevents in the daemon log for the wait window.
Remove-Item Env:\UFFS_WARM_TO_PARKED_IDLE_SECS
Remove-Item Env:\UFFS_PARKED_TO_COLD_IDLE_SECS
uffs --daemon stop
uffs --daemon start --drives C,D,E,F,G,M,SDuration: ~3 min wall-clock. Plan reference: plan task 8.3; PR #123.
WARNING — destructive. This gate deletes a drive's on-disk caches. The next search of that drive must re-read the entire MFT (cold boot, ~30-60 s for a 4 M-record drive). Pick a drive you can afford to re-build — the documented choice on the 7-drive reference box is
M:(smaller volume, less painful re-warm). DO NOT run this gate againstC:.
The daemon from G6's reset. Capture the chosen drive's on-disk cache footprint pre-forget so we can verify the freed-bytes accounting:
$drive = 'M'
$cacheRoot = "$env:LOCALAPPDATA\uffs\cache"
# Phase 8-D unlinks four canonical paths. Filenames are
# case-mixed in production (uffs-mft uses uppercase for
# `_index.{uffs,lock}`; uffs-core uses lowercase for
# `_compact.uffs` / `_usn.cursor`) — the cleaner is case-tolerant
# but the Test-Path verification has to be too.
$cachePaths = @(
"$cacheRoot\$($drive.ToLower())_compact.uffs"
"$cacheRoot\$($drive.ToLower())_usn.cursor"
"$cacheRoot\$($drive.ToUpper())_index.uffs"
"$cacheRoot\$($drive.ToUpper())_index.lock"
)
"=== Pre-forget cache footprint ==="
$total = 0
foreach ($p in $cachePaths) {
if (Test-Path $p) {
$size = (Get-Item $p).Length
Write-Host (" {0,12:N0} bytes {1}" -f $size, (Split-Path -Leaf $p))
$total += $size
}
}
" --------"
(" {0,12:N0} bytes TOTAL" -f $total)uffs --daemon forget M --forceExpected stdout:
Daemon forgot 1 drive(s); freed XX.XX MiB:
Forgotten: M
Already absent: (none)
# Verify M is gone from the registry.
"=== Post-forget status_drives — M must NOT be listed ==="
uffs --daemon status_drives
# Verify every per-drive cache file is gone.
"=== Post-forget cache files — every Test-Path must be False ==="
foreach ($p in $cachePaths) {
$exists = Test-Path $p
Write-Host (" exists={0} {1}" -f $exists, $p)
}Acceptance criteria:
forgetstdout's freed-bytes value (theDaemon forgot 1 drive(s); freed XX.XX MiBline) matches the pre-forget total within rounding.status_drivesno longer listsM.- Every per-drive cache file (
*_compact.uffs,*_usn.cursor,*_index.uffs,*_index.lock) is absent on disk.
To restore M: to the daemon, hot-load it (re-reads the MFT cold,
~30-60 s for a typical drive):
uffs --daemon load --drive MDuration: ~1 min wall-clock. Plan reference: plan task 8.4; PR #123.
uffs --daemon status_drivesPaste the full table output verbatim into the PR description.
Acceptance criteria:
- Header row exactly matches:
DRIVE TIER RESIDENT QPM LAST QUERY (ms) PIN UNTIL (ms) - One row per drive currently loaded (post-G7 this is 6 if you
forgot
M; 7 if you re-loaded it via the G7 reset). - Rows are sorted by drive letter ASCII ascending.
TIERcolumn values are lowercase (hot/warm/parked/cold).RESIDENTcolumn has the right unit suffix per tier:hot/warm⇒MiBorGiB(full body heap)parked⇒KiBorMiB(bloom + trie only)cold⇒0 B
PIN UNTIL (ms)column is-for unpinned drives, a Unix-millis integer for pinned ones (only the drive lastpreload-ed within the pin window).LAST QUERY (ms)column is-for never-queried drives, a Unix-millis integer otherwise.
Before opening the Phase 5 / Phase 6 / Phase 7 / Phase 8 acceptance PR, paste the following into the description so the reviewer can sign off without re-running the soak:
- G1 capture — log excerpt showing
Low→ cascade chain →Highwith the LRU-ordereddrive=field. - G2 capture — pair of Task Manager screenshots (peak / +5 s).
- G3 capture — Task Manager screenshot showing
I/O priority = Lowduring ashard.refreshtick window; matching log line. - G4 capture —
Get-Process uffsdtable at 0 / 30 / 60 min plus the soak-log tail. - Phase 6 24-h soak capture —
summary.txtfrom$env:USERPROFILE\uffs_soak\phase6-<timestamp>\plus the three grep-result files undervalidation/(Drive_C_never_demotes_below_Warm.pass, the per-peer-driveWarm-Parked.passfiles, andDrive_C_warm_ttl_sec_exceeds_peers__adaptive_bonus_engaged_.pass). Note: the file name pivoted fromDrive_C_chosen_ttl_sec_exceeds_peers.passto thewarm_ttl_secshape in the 2026-05-07 validator update; runs against the pre-update harness produce the older breadcrumb shape. - Phase 7 24-h soak capture —
summary.txtfrom$env:USERPROFILE\uffs_soak\phase7-<timestamp>\plus the four grep-result files undervalidation/(No_panic_OOM_FATAL.pass, both*latency*.pass,Encrypted-cache_refresh_fired.pass,Working-Set_growth_ratio.pass). Also attachsnapshots/00h-process.jsonandsnapshots/24h-process.jsonso the reviewer can independently spot-check the WS bound. - G5 hibernate capture — pre/post
status_drivesshowing every drive demoted tocold, plus theGet-ChildItem *_compact.uffslisting proving the on-disk caches were preserved. - G6 preload pin capture — pre-/post-wait
status_drivesrows forCshowingtier=hotsurvives a 90-s wait past the warm-to-parked TTL, plus the emptyletter=C ... to=parked|coldlog grep. - G7 forget capture — pre-forget cache-file size table +
post-forget
Test-Pathlisting showing all four files absent + thefreed_bytestotal from theforgetcommand's stdout. - G8 status_drives capture — full table output as it appears in the operator's terminal (header row + one row per loaded drive, sorted ASCII ascending).
After all ten captures land, update the implementation-plan §5.1 row for the corresponding phase to 🟢 with the date the PR landed.
This section documents the first end-to-end Phase 5 Windows-host
capture pass against the 7-drive reference box, run on 2026-05-02
with the v0.5.86 dev binary (the pre-canonical-event-refactor
build — the dual-logging pattern visible in the G4 excerpts below
is the very gap that the same-day refactor commit 4a627246d
closes; future capture passes against v0.5.87+ binaries will
produce one INFO shard.transition event per cascade step
instead of two). Operators running a future capture pass have a
known-good baseline to compare against.
Cross-reference: implementation-plan
docs/refactor/memory-tiering-implementation-plan.md
§3 Phase 5 "Phase 5 Windows-host validation findings (2026-05-02
capture pass, v0.5.86)" carries the per-gate analysis and the
end-to-end contract claims (LRU cascade ordering, watcher
Cascade preempted by transition out of Low mid-cascade abort,
sustained 2 h 11 min soak with no OOM).
| Gate | Artefact path (under repo root) | Wall duration | What it pins |
|---|---|---|---|
| G1 kernel notification → cascade | LOG/WINDOWS uffsd-G1G2.log (706 lines) |
~32 min (20:55 → 21:30) | Win32 watcher thread translates MEMORY_RESOURCE_NOTIFICATION Low/High into PressureSignal::Low/High events |
| G2 working-set drop ≤ 5 s | TaskMgr screenshots in PR + LOG/WINDOWS uffsd-G1G2.log lines 374-380 |
TTL idle-demote at 21:00:41 freed 4592 MB across 7 drives in 27 ms wall | Demote → EmptyWorkingSet syscall returns memory to OS within the 5 s acceptance window |
| G3 background-IO priority during USN catch-up | LOG/G3/g3-acceptance-greps.txt + LOG/G3/uffsd-G3-debug.log (1527 lines) |
~3 min 30 s (22:17:38 → 22:21:08) | BackgroundIoScope::begin() returned Err zero times across 7 successive USN refresh tick cadences (preferred capture path (a) — empty diagnostic + populated tick) |
| G4 sustained-pressure soak, no OOM | LOG/uffsd-G4.log (33 min, 116 lines) + LOG/uffsd-G4-bonus.log (2 h 11 min, 110 lines) |
combined 2 h 44 min (2.7× the 60-min G4 acceptance bar) | Daemon survives ~30 level=Low ↔ level=High cycle pairs at 30-90 s intervals; cascade preempts on transition-out-of-Low (4× during 7-drive drain); no panic, no JoinError, no shard transition fault |
Source: LOG/WINDOWS uffsd-G1G2.log lines 383-411 (12 paired
kernel/watcher events in a 24 s window) + lines 524, 529 (first
two cascade demotes).
2026-05-02T21:28:21.134825Z INFO Pressure transition observed level=Low
2026-05-02T21:28:21.134793Z INFO Memory resource notification fired level=Low
2026-05-02T21:28:21.134912Z INFO Memory resource notification fired level=High
2026-05-02T21:28:21.134936Z INFO Pressure transition observed level=High
…
2026-05-02T21:29:47.655430Z INFO Pressure cascade demoted one LRU Warm shard \
drive=C from="Warm" to="Parked" reason="pressure-cascade" \
last_query_at_ms=1777757366606
2026-05-02T21:29:49.277114Z INFO Pressure cascade demoted one LRU Warm shard \
drive=G from="Warm" to="Parked" reason="pressure-cascade" \
last_query_at_ms=1777757385120
The kernel-side Memory resource notification fired event (target
cache.pressure) and the watcher-side Pressure transition observed
event arrive within 1 ms of each other — PlatformPressureSignal::watcher
emits the second event right after WaitForMultipleObjects returns
and the watch::Sender::send_replace publishes the new level. This
end-to-end matches the deterministic Mac unit-test contract pinned
by pressure_subscriber_drains_warm_cascade_on_low_and_no_ops_on_high.
v0.5.86-pre-refactor shape. The two cascade-demote lines shown above are the OLD dual-logging format — note the
drive="Warm"(quoted-string field) in the cascade event vs theletter=C(bare-char) field on the registry primitive. Future v0.5.87+ captures will show one event per cascade step with the uniformletter=field name andreason="pressure-cascade".
Source: LOG/WINDOWS uffsd-G1G2.log lines 374-380 (TTL
idle-demote at 21:00:41, ~5 min after daemon start).
2026-05-02T21:00:41.838723Z INFO letter=G from=warm to=parked freed_mb=1 reason="demote"
2026-05-02T21:00:41.842359Z INFO letter=M from=warm to=parked freed_mb=301 reason="demote"
2026-05-02T21:00:41.845280Z INFO letter=F from=warm to=parked freed_mb=448 reason="demote"
2026-05-02T21:00:41.850675Z INFO letter=E from=warm to=parked freed_mb=474 reason="demote"
2026-05-02T21:00:41.853916Z INFO letter=C from=warm to=parked freed_mb=687 reason="demote"
2026-05-02T21:00:41.858904Z INFO letter=D from=warm to=parked freed_mb=1318 reason="demote"
2026-05-02T21:00:41.866166Z INFO letter=S from=warm to=parked freed_mb=1363 reason="demote"
All 7 drives demoted from Warm to Parked in 27 ms wall, releasing
4592 MB of body Arc state cumulatively. EmptyWorkingSet
fires once per batch (Phase 5 task 5.4 applied > 0 gate).
TaskMgr screenshots in the PR description show the corresponding
uffsd.exe Working Set drop within the 5 s acceptance window.
Source: LOG/G3/g3-acceptance-greps.txt (the runbook's preferred
capture path (a) — empty BackgroundIoPriority debug-log grep +
populated USN refresh tick cadence).
=== BackgroundIoPriority diagnostic lines (empty = success) ===
=== USN refresh tick lines ===
2026-05-02T22:26:35.723436Z INFO USN refresh tick starting count=7 interval_secs=30
2026-05-02T22:26:49.360505Z INFO USN refresh tick complete refreshed=7 failed=0 total=7 total_ms=13637
2026-05-02T22:27:05.714331Z INFO USN refresh tick starting count=7 interval_secs=30
2026-05-02T22:27:17.389393Z INFO USN refresh tick complete refreshed=7 failed=0 total=7 total_ms=11675
…
Empty diagnostic = BackgroundIoScope::begin() returned Ok
on every per-letter spawn_blocking worker across 7 successive
30 s refresh ticks (each ~11-13 s wall for 7 drives totalling
25.7 M records). No leaked thread-priority elevations
(Drop::drop paired THREAD_MODE_BACKGROUND_END correctly via
the RAII guard). Full debug log: LOG/G3/uffsd-G3-debug.log.
Source: LOG/uffsd-G4.log (33 min, daemon-restart phase) +
LOG/uffsd-G4-bonus.log (2 h 11 min, sustained pressure).
Combined wall 2 h 44 min, 2.7× the runbook's 60-min G4 bar.
uffsd-G4-bonus.log lines 38-69 capture a 7-step LRU cascade
under sustained kernel-Low pressure (excerpted):
2026-05-02T23:08:11.134135Z INFO Memory resource notification fired level=Low
2026-05-02T23:08:11.134161Z INFO Pressure transition observed level=Low
2026-05-02T23:08:11.134631Z INFO letter=G from=warm to=parked freed_mb=1 reason="demote"
2026-05-02T23:08:11.145475Z INFO Memory resource notification fired level=High
2026-05-02T23:08:11.970112Z INFO Pressure cascade demoted one LRU Warm shard \
drive=G from="Warm" to="Parked" reason="pressure-cascade" \
last_query_at_ms=1777763174381
2026-05-02T23:08:11.970271Z INFO Cascade preempted by transition out of Low new_level=High
…
Three end-to-end contracts demonstrated in this excerpt:
-
LRU cascade ordering under fully-tied input. All 7 cascade-demote events carry the same
last_query_at_ms=1777763174381because the operator drove zero queries before the soak — the in-memory clock skew betweenDriveStats::last_query_at_msof different shards collapsed to a single sample. Thecascade_demote_one_stepper-call iteration through theoldest-last_query_at_msheuristic still drained one shard per cascade tick (vs dumping all 7 at once) per the Phase 5 task 5.10 contract. -
Cascade-preempt-on-High via
rx.has_changed(). Lines 43, 49, 55, 65 (4 of 7 cascade steps) showCascade preempted by transition out of Low new_level=High— the kernel briefly recovered headroom mid-soak, the watcher thread translated the recovery to aPressureSignal::Highsend, and the cascade subscriber'srx.has_changed()poll between iterations caught it before over-shedding remaining shards. -
Dual-logging in the wild (now fixed at the source). Each cascade step in this excerpt emits two INFO events: the registry primitive's
letter=G from=warm to=parked freed_mb=1 reason="demote"(line 40) followed by the cascade's redundantPressure cascade demoted one LRU Warm shard drive=G ... reason="pressure-cascade"(line 42), separated by 1339 ms (theEmptyWorkingSetsyscall on the first cascade demote, dropping to ~6 ms on subsequent ones). Operator counting cascade demotes by greppingreason="pressure-cascade"would see 7 events; counting byletter=field would see 14 (each cascade step double-counted). Commit4a627246d(same-day refactor) collapses these into one event withreason="pressure-cascade"; future capture passes will not exhibit this pattern.
Source: LOG/uffs_soak/phase6-20260509-213122/ (24-h run on the
7-drive reference box, May 9-10 2026).
Run summary: 8 of 9 harness assertions PASS; 1 assertion deferred to a re-run with the post-2026-05-13 harness fix.
| Contract (from §2 above) | 24-h evidence | Status |
|---|---|---|
1. C never demotes below Warm |
0 to=Parked events for letter=C; 2 871 min-tier-clamp debug events |
✅ end-to-end verified |
2. Peer drives demote Warm → Parked normally |
D / E / F / G / M / S each fired ≥ 2 Warm→Parked transitions | ✅ end-to-end verified |
3. Adaptive TTL bonus (+600·log2(rate)) engages under load |
Daemon computed warm_ttl_sec ≈ 3 687 s every tick during the synthetic-load window but emitted it only at TRACE; harness's RUST_LOG=shard.ttl=debug filter dropped every below-ttl event |
Root cause of the deferred criterion. crate::index::transitions:: evaluate_idle_demote emits its shard.ttl event at one of three
levels depending on the demote-eval ladder's outcome:
| Arm | Level | Fires when |
|---|---|---|
idle-demote |
DEBUG | drive idle past TTL → demote target accepted |
min-tier-clamp |
DEBUG | drive idle past TTL → demote suppressed by min_tier floor |
below-ttl |
TRACE | drive not yet idle past TTL (the catch-all) |
During the synthetic-load window drive C sits in Warm/Hot with
idle_secs ≈ 0, so the demote-eval ladder never reaches either
DEBUG arm — only the TRACE-level below-ttl event fires, carrying
the bonused warm_ttl_sec field that criterion 3 scrapes for.
The pre-2026-05-13 runbook RUST_LOG was
shard.ttl=debug, filtering the trace events out.
Fix landed in PR #218 (2026-05-13):
scripts/dev/long-soak.rs:746—shard.ttl=debug→shard.ttl=trace. Cost: ~23 k extra trace events over 24 h (~3.5 MB), marginal against the existing 75 MB log volume the WARN journal-not-active spam already produces.crates/uffs-daemon/src/index/tests/shard_ttl_events.rs:: below_ttl_event_pins_target_level_message_and_reason— daemon-side regression test pinning target =shard.ttl, level = TRACE, message ="Adaptive idle-demote evaluation: not yet idle past TTL",reason="below-ttl", and the four TTL fields the harness'sparse_max_ttl_fieldreads.
The Phase 6 contract is satisfied at code + unit-test level
(the EMA-integration formula is pinned by
crate::cache::shard::tests::decay_ema_integrates_new_queries_into_rate_estimate
from PR #146; the field shape is pinned by the new regression
test above). Direct end-to-end evidence of the adaptive bonus
engaging during a synthetic-load window was captured in
the post-PR-218 re-run on 2026-05-14 — see §4.5e below for the
closing capture.
Source: LOG/uffs_soak/phase7-20260510-214412/ (24-h run on the
7-drive reference box, May 10-11 2026).
Run summary: 6 of 7 harness assertions PASS at run time; 7
of 7 with the post-2026-05-13 validator regex fix (no new soak
required — the fix is a pure regex change against the existing
24-h daemon.log).
| Contract (from §3 above) | 24-h evidence | Status |
|---|---|---|
| 1. New-item latency ≤ 2 s | initial probe = 14 ms, final probe = 18 ms | ✅ end-to-end verified |
| 2. Encrypted-cache refresh fired ≥ 1× over 24 h | 11 Journal poll: triggered background compact-cache save events captured |
✅ end-to-end verified (after regex fix) |
3. uffsd.exe Working Set ≤ 1.5× over 24 h |
first=7 259 754 496 B, last=12 767 232 B, ratio=0.00× | ✅ within bound (see footnote) |
4. No panic / OutOfMemoryError / FATAL |
0 fatal-class log lines | ✅ end-to-end verified |
| harness bonus Demote-to-Parked count ≤ 12 | 6 to=Parked events (ceiling 12) |
✅ within bound |
Root cause of the single PASS-after-fix. The pre-fix
validator's regex was a speculative
USN refresh tick|trigger_save|threshold.*save|encrypted cache refresh
— none of those alternatives match the daemon's actual INFO
line Journal poll: triggered background compact-cache save.
The save pipeline was healthy all along; the validator was just
hunting for strings the daemon never emits.
Fix landed in PR #218 (2026-05-13):
scripts/dev/long-soak.rs:1244— regex re-anchored oncompact-cache save. Retroactively passes the existing 24-h log:grep -c 'compact-cache save' \ LOG/uffs_soak/phase7-20260510-214412/daemon.log # → 11
crates/uffs-daemon/src/cache/journal_loop/tests/ save_log_message.rs— daemon-side regression test pinning target =uffs_daemon::cache::journal_loop, level = INFO, and the literalcompact-cache savesubstring so a future log- message rename fails CI before reaching a 24-h soak.
Footnote on the Working-Set ratio (criterion 3). The ratio passed the ≤ 1.5× bound with a 500× drop over 24 h (
7 259 754 496 B→12 767 232 B). Initially flagged as a potential vacuous pass (suspected idle-decay), but resolved by the 2026-05-13 ws-trace capture (§4.5d below): the same 30× drop was observed in ws-trace while the keep-warm worker held all 7 drives in Warm across 24 h, andpm_bytes(commit-charge) stayed essentially flat throughout. Both soaks' WS drops are the benign Phase 5 G2EmptyWorkingSetpage-trim, not silent idle-decay or leak. See §4.5d for the fullws_bytes-vs-pm_bytesbreakdown.
Phase 7 closes retroactively — no new 24-h soak required.
The validator-only re-run can be done by replaying the existing
daemon.log through the fixed scripts/dev/long-soak.rs
validate_phase7 (manual grep shown above suffices for the
acceptance bar).
Source: LOG/uffs_soak/wstrace-20260513-113344/ (24-h
observe-only Working-Set trajectory on the 7-drive reference
box, May 13-14 2026).
Run summary: 4 of 4 harness assertions PASS with a measurement nuance worth documenting before the v0.6.0 cut.
Assertion (from memory-tiering-bake-criteria.md §1.7) |
24-h evidence | Status |
|---|---|---|
| ≥ 20 hourly snapshots captured | 24 snapshots in snapshots/*-process.json + snapshots/*-status-drives.txt |
✅ |
| Keep-warm worker fired ≥ 216 probes | 289 / 289 fired, zero errors in keep-warm.log |
✅ |
| Daemon PID at hour 24 == PID at hour 0 | PID 50492 across all 24 samples | ✅ |
| Working Set at hour 24 ≤ 1.5× Working Set at hour 0 | first=5 367 414 784 B, last=184 193 024 B, ratio=0.03× | ✅ |
The catch: ws_bytes is NOT the right proxy for "no leak" on
Windows. wstrace.csv shows a 30× drop in ws_bytes at the
03h → 04h boundary (5.37 GB → 160 MB), but at the same sample:
pm_bytes(Private Memory Size, the OS's commit-charge for the process) actually increased by ~870 MB (6.53 GB → 7.40 GB), then settled to 6.36 GB by 06h and held there for the remaining 18 h.- The daemon's own per-drive RESIDENT accounting in
04h-status-drives.txtis identical to03h-status-drives.txt: all 7 drives still Warm with the same ~5.0 GiB cumulative body-Arc footprint (C=715 MiB, D=1.30 GiB, E=485 MiB, F=466 MiB, G=1 MiB, M=311 MiB, S=1.36 GiB). - The keep-warm worker fired without errors across the
03h → 04h boundary (probes #37-#48 all
OKinkeep-warm.log).
Conclusion: the WS drop is the EmptyWorkingSet
page-trim mechanism (the Phase 5 G2 wiring via
crate::cache::working_set_trim::WorkingSetTrim), not a tier
transition or memory release. Pages moved from the daemon's
resident WS into the OS standby list; underlying private bytes
stayed allocated and the data is still arc-held on heap. On
next access the pages re-fault from standby with no disk I/O.
Three orthogonal readings of the same 24 h:
Working Set : 5 367 414 784 B → 184 193 024 B (0.03×) ← OS view, not a leak signal
Private Memory : 6 534 524 928 B → 6 355 034 112 B (0.97×) ← commit-charge, real leak signal
Daemon RESIDENT : 5.0 GiB → 5.0 GiB (1.00×) ← daemon's body-Arc accounting
The daemon decreased committed memory by 3 % over 24 h while holding 7 drives in WARM and serving 289 probes. No leak.
Implication for the §4.5c Phase 7 footnote. The "vacuous
pass" concern raised there (Phase 7's WS ratio = 0.00× being
suspicious because the daemon might have demoted everything to
Parked) is resolved. ws-trace's keep-warm worker held the
daemon in Warm steady-state across 24 h and the daemon still
showed the same 30× WS drop — so the Phase 7 WS drop is the
same benign EmptyWorkingSet page-trim, not silent idle-decay.
Both soaks were healthy.
Recommended future refinement (NOT a v0.6.0 blocker).
scripts/dev/long-soak.rs should additionally surface
pm_bytes and re-anchor the assertion on it, since on Windows
it's the leak-relevant metric. Tracked informally for
post-v0.6.0; not a blocker because:
pm_bytesis already captured in everyGet-Processsnapshot (snapshots/*-process.jsonhas it under thePMfield) — the evidence is on disk regardless of which field the assertion uses.- The current
ws_bytesassertion still catches a real leak reliably: any process that's leaking would grow both WS and private bytes monotonically. The "0.03× ratio" pass is directionally correct (no growth = no leak), just numerically misleading.
ws-trace closes — all 4 assertions PASS end-to-end on the existing capture; no re-run needed.
Source: LOG/uffs_soak/phase6-20260514-122946/ (24-h run on the
7-drive reference box, 2026-05-14 12:29:46Z → 2026-05-15
12:29:46Z, against the post-PR-218 harness fix).
Run summary: 9 of 9 harness assertions PASS — the §4.5b deferred adaptive-bonus criterion now has direct end-to-end evidence.
| Contract (from §2 above) | 24-h evidence | Status |
|---|---|---|
1. C never demotes below Warm |
0 to=Parked events for letter=C; 2 870 Demote target clamped by per-drive min_tier debug events |
✅ end-to-end verified |
2. Peer drives demote Warm → Parked normally |
D / E / F / G / M / S each fired 2 Warm→Parked transitions | ✅ end-to-end verified |
3. Adaptive TTL bonus (+600·log2(rate)) engages under load |
C.max_warm_ttl=3 786 s vs max(peers.max_warm_ttl)=300 s — bonus = 12.6× peer baseline | ✅ end-to-end verified (was §4.5b |
Why this re-run was needed. The §4.5b deferral was a
harness-side log-level filter: the RUST_LOG=shard.ttl=debug
filter dropped every below-ttl TRACE event, which is the only
event class that carries the bonused warm_ttl_sec field
during the synthetic-load window (drive C sits in Warm/Hot
with idle_secs ≈ 0, so the demote-eval ladder never reaches
either DEBUG arm). PR #218 raised the harness filter to
shard.ttl=trace; this re-run is the first 24-h soak captured
against that fix.
Memory trajectory. In addition to the 9 contract assertions, the hourly process snapshots show the tiering machinery doing real work:
00h 23h post-load
Working Set (WS) : 6 746 800 128 → 22 888 448 → 69 238 784 (308× WS trim, 3× post-load)
Private Memory : 8 293 457 920 → 1 791 188 992 → 1 669 558 272 (78 % drop, real release)
Virtual Memory : 28 172 120 064 → 28 168 974 336 → 28 168 974 336 (flat — no address-space leak)
NPM (non-paged) : 26 736 → 26 328 → 26 328 (flat)
This is materially different from §4.5d's ws-trace
trajectory, where pm_bytes stayed within 3 % over 24 h
because the keep-warm worker held all 7 drives in Warm. Here
the controller actively demoted the 6 peer drives Warm → Parked
twice each, which unloaded cold shards from memory and produced
the 78 % private-memory release — exactly the intended
tiering-machinery behavior under sustained idle.
The synthetic-load window at end-of-soak then re-paged recently-needed shards back into WS (22 MiB → 66 MiB, 3×) without growing private memory (which actually continued to fall slightly), confirming the page-cache vs. private-bytes split is healthy: the daemon brings pages back from standby on access rather than re-allocating.
Operational signals (informational, not gate criteria).
daemon.logsize: 530 454 lines / 78 MiB. Bulk of the volume is the expectedjournal_loop=infoper-tick TRACE on drives whose USN journal isn't active (M and G — non-system drives with no journal enabled, a benign Win32 error 1179 surfaced asWARN Journal poll failed; retrying next tick). The PR-#218shard.ttl=tracefilter added an additional ~23 k events as predicted in §4.5b.0panic/OutOfMemoryError/FATALlog lines across 24 h — same clean-run shape as §4.5c Phase 7.- All 24 hourly snapshots captured (
snapshots/00h-process.jsonthroughsnapshots/23h-process.jsonplussnapshots/post-load-process.json). - All 9
validation/*.passbreadcrumb files written.
Phase 6 closes — 9 of 9 assertions PASS end-to-end against
the live Windows host; no further re-runs needed. The
bake-criteria.md §3 Phase-6 checkbox can now be ticked.
Combined with §4.5c (Phase 7 closes retroactively), §4.5d
(ws-trace closes), and the existing Phase 8 closure from
2026-05-05, this exhausts the v0.6.0 24-h-soak gate slate.
Only the one-week main bake remains per
memory-tiering-bake-criteria.md.
Source: LOG/uffsd-G4-bonus.log line 104 — at 01:17:15 (2 h 11 min
after daemon start), the lifecycle controller logged:
2026-05-03T01:17:15.019200Z ERROR Load stalled — no drive progress, \
force-retiring stall_secs=300 heartbeat_age_secs=7864
2026-05-03T01:17:15.019985Z INFO Daemon shutting down
Root cause: LifecycleManager::run_idle_timer interprets "no
drive-loading progress" as a stall, but a daemon serving zero
queries against 7 fully-Parked drives has no drive-loading
progress to make — the heartbeat hasn't ticked because there's
nothing to do. This is a Phase 7 / lifecycle-controller scope
item, not a Phase 5 regression: the load-stall semantics need
to distinguish "load incomplete, no progress" (legitimate stall)
from "load complete, no demand" (legitimately idle). Tracked in
crates/uffs-daemon/src/lifecycle.rs (file-size
permanent-exception, see scripts/ci/file_size_exceptions.txt).
G4 acceptance bar (no OOM through 60 min) was met independently
of this — the 01:17 force-retire happened at the 2 h 11 min mark,
well past the gate window.