Oregami
Repositories/oxedyne/ore

oxedyne/ore/cli/tests/memory.rs

14.6 KiB, 5 runs

created by r2848102244:744, which is this file's identity for as long as the history lasts, whatever it is later renamed to

download · who wrote it · its history

1//! What a repository costs to OPEN, measured on a real history.
2//!
3//! # The failure this guards
4//!
5//! On 2026-08-20 a 44,628-operation store cost 345,272 kB of peak resident
6//! memory to read, 7.63 kB for every operation in it, because the inserted bytes
7//! of every splice were held three times over: once in the log's `Record`, once
8//! in the `Applied` the sequence cloned, and once again in `Atoms`. Giving the
9//! three one buffer to share took it to 5.79. Dropping the envelopes for every
10//! verb that never hands an operation on, and dropping the snapshots, took it to
11//! **3.79**, which is the first reading under the 5 kB budget.
12//!
13//! This test fails above 4.5, which is between the two, so a change that puts a
14//! second copy back reddens here rather than on somebody's phone.
15//!
16//! # Why `ore log` and not `ore sync`
17//!
18//! The peak was first found on a clone and blamed on the transport. It is not
19//! the transport: `ore log` touches no network, reads a local store, and costs
20//! the same. Every verb that opens the repository pays it, so a user who has
21//! never once synced pays it too. `ore log` is therefore the cheapest way to
22//! reproduce the whole peak, and the honest one.
23//!
24//! # Why a real history and not a fixture
25//!
26//! The cost is per operation and the content is what dominates it, so a
27//! synthetic history built from short strings measures the struct sizes -- about
28//! 344 bytes an operation, four percent of the figure -- and says nothing about
29//! the rest. The fixture is a real replica at [`FIXTURE`]; where it is absent
30//! this test says so on the real standard error and returns, because a guard
31//! that quietly passes on the machines that lack its subject is worse than none.
32//!
33//! It is slow. `ore log` over 44,628 operations takes half a minute built for
34//! release, and five and a half minutes built for debug, which is how
35//! `cargo test` builds it.
36
37mod support;
38
39use support::{
40 operations,
41 Scratch,
42};
43
44use oxedyne_fe2o3_core::prelude::*;
45
46use std::io::Write as IoWrite;
47use std::path::{
48 Path,
49 PathBuf,
50};
51use std::process::Command;
52
53
54/// The replica the budget was measured against, under the user's home
55/// directory.
56///
57/// A pull of `oxedyne/daimond-src` into an empty directory, kept because it is
58/// the only history to hand large enough for the floor to be noise. See
59/// `~/usr/code/ai/claude/audit/rc1-ore-relay-20260820/README.md`.
60const FIXTURE: &str = ".cache/ore-trial/clone2";
61
62/// Names another repository to measure instead, for a machine that keeps its
63/// large history somewhere else.
64const FIXTURE_ENV: &str = "ORE_MEMORY_FIXTURE";
65
66/// kB of peak resident memory per operation, above the binary's own floor, at
67/// which the guard fails.
68///
69/// 7.63 when this was first measured, 5.79 once the content of an edit was held
70/// once rather than three times, and **3.79 now**, after the envelopes stopped
71/// being kept by every verb that never hands an operation on and the snapshots
72/// stopped being written at all.
73///
74/// **The budget is 5 kB per operation and it is now met.** It was set from
75/// Daimond's measured ceiling, iOS having killed a tab at 1,639 MB, with Ore one
76/// tenant in that and wasm linear memory never shrinking, so a peak there is a
77/// permanent floor. This is the first reading under it.
78///
79/// So the guard comes down with the figure, to sit between what is measured and
80/// what is owed. **It must not go up.** A ceiling left where the old cost was
81/// would wave through a regression of seventy per cent, which is the whole of
82/// what has been won since. If a change pushes past this, the change is wrong or
83/// the budget argument has changed, and the second of those is settled with the
84/// owner rather than in this file.
85const CEILING: f64 = 4.5;
86
87/// What the same reading costs once the working copy index says nothing has
88/// moved, in kB an operation.
89///
90/// A command that captures nothing renders nothing, and the render is 100 MB of
91/// the 165 an `ore log` cost before there was an index: measured at 1.53 kB an
92/// operation against the 3.68 above. This bound is 2.0, which is between the
93/// two, so a change that quietly stopped the index engaging reddens here rather
94/// than on somebody's phone. It is a REGRESSION bound like [`CEILING`] and it
95/// comes down, never up.
96const INDEXED_CEILING: f64 = 2.0;
97
98// The figures this ceiling was set from -- 7.63 kB per operation before the
99// content was shared and 5.79 after -- were measured on a RELEASE binary, and
100// `CARGO_BIN_EXE_ore` is whatever profile the suite was built in, normally
101// debug. A debug binary is the more generous case for a ceiling, since it
102// carries more of everything, so a debug run passing at 6.5 implies a release
103// run passes too and the guard stays honest either way. It is stated here
104// because the failure message quotes release numbers, and a reader comparing
105// them against a debug measurement would otherwise be comparing two things.
106
107/// Below this many operations the binary's floor is a large enough share of the
108/// reading to swamp what is being measured, so there is nothing to conclude.
109const FLOOR_IS_NOISE_ABOVE: usize = 10_000;
110
111/// The measuring program, which reports a peak the process itself cannot see
112/// once it has exited.
113const TIME: &str = "/usr/bin/time";
114
115/// The line of its report that carries the high water mark.
116const WATERMARK: &str = "Maximum resident set size (kbytes):";
117
118
119/// Returns the repository to measure, or nothing if it is not on this machine.
120fn fixture()
121 -> Outcome<Option<PathBuf>>
122{
123 if let Ok(named) = std::env::var(FIXTURE_ENV) {
124 let path = PathBuf::from(named);
125 return match path.join(".ore").is_dir() {
126 true => Ok(Some(path)),
127 false => Err(err!(
128 "{} names {:?}, which is not an Ore repository.", FIXTURE_ENV, path;
129 Test, Missing)),
130 };
131 }
132 let home = match std::env::var("HOME") {
133 Ok(h) => PathBuf::from(h),
134 Err(_) => return Ok(None),
135 };
136 let path = home.join(FIXTURE);
137 Ok(match path.join(".ore").is_dir() {
138 true => Some(path),
139 false => None,
140 })
141}
142
143/// Copies a repository, so the measurement never touches the original.
144fn copy_tree(from: &Path, to: &Path)
145 -> Outcome<()>
146{
147 let out = match Command::new("cp").arg("-a").arg(from).arg(to).output() {
148 Ok(o) => o,
149 Err(e) => return Err(err!(e,
150 "{:?} could not be copied to {:?}.", from, to; Test, IO)),
151 };
152 if !out.status.success() {
153 return Err(err!(
154 "Copying {:?} to {:?} failed: {}", from, to,
155 String::from_utf8_lossy(&out.stderr).trim();
156 Test, IO));
157 }
158 // The lock file comes across with everything else and is nothing in the copy:
159 // it is where an advisory lock is kept and not the lock, so nobody holds it
160 // here. It is cleared rather than removed, so that a note copied from a tree
161 // somebody is working in does not name a process in the wrong one.
162 let lock = to.join(".ore").join("lock");
163 if lock.is_file() {
164 let _ = std::fs::write(&lock, b"");
165 }
166 Ok(())
167}
168
169/// Says on the real standard error what the guard measured.
170fn report(what: &str) {
171 let mut handle = std::io::stderr();
172 let _ = handle.write_all(fmt!(
173 "\n*** MEMORY opening_a_large_history_does_not_regress_toward_a_second_copy: {}\n\n",
174 what,
175 ).as_bytes());
176 let _ = handle.flush();
177}
178
179/// Says on the real standard error that the guard did not run, and why.
180///
181/// `println!` and `eprintln!` are taken by the test harness and shown only when
182/// a test fails, so a skip announced through either is a skip nobody reads. A
183/// write to the handle goes to the descriptor and past the capture.
184fn skip(why: &str) {
185 let mut handle = std::io::stderr();
186 let _ = handle.write_all(fmt!(
187 "\n*** SKIPPED opening_a_large_history_does_not_regress_toward_a_second_copy: {}\n\n",
188 why,
189 ).as_bytes());
190 let _ = handle.flush();
191}
192
193/// Runs the compiled binary under the measuring program, returning its peak
194/// resident size in kB and what it printed.
195fn peak_kb(dir: &Path, args: &[&str])
196 -> Outcome<(u64, String)>
197{
198 let out = match Command::new(TIME)
199 .arg("-v")
200 .arg(env!("CARGO_BIN_EXE_ore"))
201 .args(args)
202 .current_dir(dir)
203 .output()
204 {
205 Ok(o) => o,
206 Err(e) => return Err(err!(e,
207 "`{} -v ore {}` could not be run in {:?}.", TIME, args.join(" "), dir;
208 Test, IO)),
209 };
210 let report = fmt!("{}", String::from_utf8_lossy(&out.stderr));
211 if !out.status.success() {
212 return Err(err!(
213 "`ore {}` failed in {:?}: {}", args.join(" "), dir, report; Test, IO));
214 }
215 let mut peak: Option<u64> = None;
216 for line in report.lines() {
217 let at = match line.find(WATERMARK) {
218 Some(i) => i + WATERMARK.len(),
219 None => continue,
220 };
221 peak = match line[at..].trim().parse::<u64>() {
222 Ok(n) => Some(n),
223 Err(e) => return Err(err!(e,
224 "What follows {:?} is not a number: {}", WATERMARK, line; Test, Mismatch)),
225 };
226 break;
227 }
228 let peak = res!(peak.ok_or_else(|| err!(
229 "{} -v did not report {:?}: {}", TIME, WATERMARK, report; Test, Missing)));
230 Ok((peak, fmt!("{}", String::from_utf8_lossy(&out.stdout))))
231}
232
233
234/// Reading a large history costs no more than [`CEILING`] kB an operation.
235///
236/// It guards against the content of an operation being held more than once
237/// while the repository is open, which cost 7.63 kB an operation until
238/// `Op::Splice { insert }` became an `Arc<[u8]>` that the log, the sequence and
239/// the atoms share.
240#[test]
241fn opening_a_large_history_does_not_regress_toward_a_second_copy() -> Outcome<()> {
242 let fixture = match res!(fixture()) {
243 Some(f) => f,
244 None => {
245 skip(&fmt!(
246 "there is no repository at ~/{} to measure. Clone a large history there, \
247 or name one in {}. The memory budget is NOT being checked on this machine.",
248 FIXTURE, FIXTURE_ENV,
249 ));
250 return Ok(());
251 },
252 };
253 if !Path::new(TIME).is_file() {
254 skip(&fmt!(
255 "{} is not installed, and the peak resident size cannot be read back from a \
256 process that has exited without it. The memory budget is NOT being checked \
257 on this machine.", TIME,
258 ));
259 return Ok(());
260 }
261
262 // The floor is what the binary costs before it has opened anything, and it
263 // is taken here rather than written down because it moves between a debug
264 // build and a release one -- 7,016 kB against 4,376 kB when this was
265 // written, which is a tenth of a kB an operation either way.
266 let scratch = res!(Scratch::new("memory_floor"));
267 let (floor, _) = res!(peak_kb(&scratch.path, &[]));
268
269 // MEASURED ON A COPY, never on the fixture itself.
270 //
271 // Two reasons, both found by running it. Every verb but `init` captures
272 // before it reports, so measuring in place WRITES to a repository outside the
273 // workspace -- `cargo test` silently lengthening the user's own history is not
274 // a side effect a test may have. And the repository takes an exclusive lock,
275 // so a second test binary, a second `cargo test`, or the user running `ore` in
276 // that directory turns this guard red for a reason that has nothing to do with
277 // memory. It failed exactly that way on its first run beside the rest of the
278 // suite.
279 //
280 // The copy costs a little over a hundred megabytes of disk and a second or two,
281 // and it buys a measurement that is hermetic, repeatable and safe to run
282 // concurrently. The peak being measured is the reader's, and it does not care
283 // which directory the bytes came from.
284 let bench = res!(Scratch::new("memory_bench"));
285 let target = bench.path.join("clone");
286 res!(copy_tree(&fixture, &target));
287 let (peak, text) = res!(peak_kb(&target, &["log"]));
288 let ops = res!(operations(&text));
289 if ops < FLOOR_IS_NOISE_ABOVE {
290 skip(&fmt!(
291 "{:?} holds {} operations, and below {} the binary's own {} kB floor is too \
292 large a share of the reading to say anything. The memory budget is NOT being \
293 checked on this machine.", fixture, ops, FLOOR_IS_NOISE_ABOVE, floor,
294 ));
295 return Ok(());
296 }
297 if peak <= floor {
298 return Err(err!(
299 "Opening {:?} peaked at {} kB, no more than the {} kB the binary costs \
300 having opened nothing. The measurement is wrong, not the code.",
301 fixture, peak, floor;
302 Test, Mismatch));
303 }
304
305 let above = peak - floor;
306 let per_op = (above as f64) / (ops as f64);
307 // Said out loud on a pass, not only on a failure.
308 //
309 // A guard that reports nothing when it holds tells a later reader only that it
310 // did not fire, and the number is the whole point of it: the difference
311 // between 6.4 and 5.8 is the difference between a guard about to start
312 // failing and one with room in it. Written past the harness capture for the
313 // same reason [`skip`] is.
314 report(&fmt!("{:.2} kB per operation ({} kB peak, {} kB floor, {} operations)",
315 per_op, peak, floor, ops));
316 assert!(
317 per_op <= CEILING,
318 "Opening {:?} cost {:.2} kB per operation, over the {:.2} kB REGRESSION bound \
319 (which is not the budget -- the budget is 5.00 and was already missed): {} kB peak, \
320 {} kB of that the binary's floor, {} kB over it, across {} operations. The content \
321 of an operation is being held more than once while the repository is open; it was \
322 7.63 kB per operation when the log, the sequence and the atoms each kept a copy, \
323 and 5.79 once they shared one.",
324 fixture, per_op, CEILING, peak, floor, above, ops,
325 );
326
327 // AND AGAIN, with the index the first reading left behind.
328 //
329 // The two are measured in one test and on one copy on purpose: the first
330 // establishes the index and the second uses it, so the pair says what the
331 // index is worth on the same bytes on the same machine in the same second.
332 // Kept as a guard rather than reported and forgotten, because an index that
333 // silently stopped engaging would cost 100 MB a command and nothing would
334 // fail: everything it does is invisible from the outside except the peak.
335 let (again, text) = res!(peak_kb(&target, &["log"]));
336 if res!(operations(&text)) != ops {
337 return Err(err!(
338 "The second reading of {:?} found {} operations where the first found {}, so \
339 the two are not measuring one repository.",
340 fixture, res!(operations(&text)), ops;
341 Test, Mismatch));
342 }
343 if again <= floor {
344 return Err(err!(
345 "The second reading of {:?} peaked at {} kB, no more than the {} kB floor.",
346 fixture, again, floor;
347 Test, Mismatch));
348 }
349 let indexed = ((again - floor) as f64) / (ops as f64);
350 report(&fmt!("with the working copy index: {:.2} kB per operation ({} kB peak), \
351 against {:.2} without it", indexed, again, per_op));
352 assert!(
353 indexed <= INDEXED_CEILING,
354 "Reading {:?} a second time cost {:.2} kB per operation, over the {:.2} kB \
355 REGRESSION bound: {} kB peak against {} kB for the first reading. The working \
356 copy index is not stopping the render -- either it is not being written, or it \
357 is not being believed, and neither says so on its own.",
358 fixture, indexed, INDEXED_CEILING, again, peak,
359 );
360 assert!(
361 indexed < per_op,
362 "Reading {:?} twice cost the same both times ({:.2} kB an operation), so the \
363 first reading left no index or the second did not use it.",
364 fixture, indexed,
365 );
366 Ok(())
367}