# Cause Test: operations log

This log records how the locked run is carried out. It is not part of the plan, the lock or any result, and nothing
in it changes them. Times are Halifax time.

## 2026-10-12

**16:58: the plan was locked.** cause_lock.json, SHA-256
32d72d1e2a4b67a3642e3cdce0207b43e0af670683609c8d84fb1b00366da527. Before the freeze, all ten files matched the
fingerprints shown to Colson, and the freeze's own checks passed.

**Operational delay: the machine slowed down.** The workspace had restarted at 16:49. Since then, the same code has run
1.8 to 2.2 times slower than in the checks earlier in the day. The hardware is shared, and up to 16% of processor time
went to other users. At that speed a base run needs about 4 to 5 minutes alone and about 6 with seven at once. A base
piece could not finish inside the run's hard limit of 285 seconds per piece (the plan: under 5 minutes). A piece that
is cut off saves nothing and is repeated, so it would be repeated without end.

This is an operational delay, not an experimental failure. No piece has been launched: no new start (19 to 60) has
been run, and there is no run log, no part and no saved run. The plan, the code, the lock and every fingerprint are
unchanged, and so is the way the run is carried out. At 17:25 the lock's 16 fingerprints and the settings were checked
again and all match.

**Colson's decision (about 17:20): wait for the speed to return.** The locked protocol stays as written, including
foreground pieces under the hard limit. The execution method and the frozen files are not changed. If the speed stays
too low, the run stays paused rather than launching pieces that would be cut off. No new start, no publication and no
website changes until the original requirements can be met. The integrity of the experiment comes before the time it
takes to finish.

### How the speed is judged before resuming (set before measuring)

The existing check (`python3 -B cause_test.py check`: old start 1 only; writes nothing) prints two times:

- b, the base-run code for 300 time units of settling and the first 50 of the run;
- r, six branches for 25 time units each, stepping exactly as the run's two copies do.

From these:

- a full base run (300 of settling, then 6,000) takes about b + (5,950 / 150) r = b + 39.7 r;
- a moment piece takes about 2 × (20 r + 1 s): a moment task runs its six branches for 500 time units (20 × 25), and
  14 moment tasks on 7 workers take two rounds.

Colson asked for a margin of about 20% for fluctuations. Both must come to at most 228 s, which leaves at least 20% of
the 285-second limit unused.

1. **One check alone.** If its full base run comes to more than 228 s, the run stays paused, and step 2 is not run.
2. **Seven copies of the check at once**, as a base piece runs seven base runs at once. They run in one foreground
   command that ends when they do (about a minute) and writes nothing. The run resumes only if every check reads True
   and, for the slowest copy, both the full base run and the moment piece come to at most 228 s.
3. **During the run:** if a piece takes longer than 228 s or is cut off by the limit, the run pauses, and steps 1 and 2
   are repeated before any further piece. No piece is launched while the benchmark fails.

### Speed measurements

| when | b | r | full base run | moment piece |
| --- | --- | --- | --- | --- |
| earlier on Oct 12 (two checks, one alone each) | 9.4 to 10.9 s | 3.3 to 3.4 s | 140 to 146 s | 134 to 138 s |
| 16:57 to 17:15 (three checks after the restart, one alone each) | 15.6 to 17.1 s | 5.8 to 7.3 s | 247 to 306 s | 234 to 294 s |
| 17:25 (step 1: one check alone) | 10.6 s | 2.7 s | 118 s | 110 s |
| 17:26 (step 2: seven checks at once; the slowest copy's figures) | 8.3 to 8.9 s | 2.8 to 3.1 s | 132 s | 126 s |

**17:26: the benchmark passed, and the run resumes under the locked protocol, unchanged.** Every check read True in
all seven copies. The slowest copy's full base run (132 s) and moment piece (126 s) are both under 228 s, which leaves
more than 20% of the 285-second limit unused. Up to 16% of processor time had been going to other users; none was now.

**17:27 to 17:31: piece 1 finished in 267 s.** It ran the base runs for starts 19 to 25. All seven tasks were done and
logged, taking 227 to 267 s, inside the 285-second limit. No task failed and nothing was cut off. As always, the piece
printed only counts and times.

**17:31: paused (step 3).** The piece took longer than 228 s, so the run is paused before piece 2. The benchmark had
projected 132 s for a base piece, and the piece took twice that. The check lasts about 13 seconds, and the speed the
machine showed in so short a burst did not hold while seven full runs went on for minutes. Steps 1 and 2 therefore
cannot show that a piece will finish with the margin, so they are not repeated as written. Colson is asked how to go
on. 7 of 462 tasks are done. The next piece would be the base runs for starts 26 to 32.

### Investigating the slowdown (Colson's request, about 17:40; set before measuring)

Colson asked for the run to stay paused while the sustained slowdown is investigated: read-only system diagnostics,
and a representative workload that produces no outcome, never short bursts. He asked whether running fewer tasks at
once could help without changing the frozen scientific protocol. Any change to how the run is carried out is to be
put to him for approval before it is made. The 285-second limit and the 228-second target stay. Piece 2 does not start
until its runtime has been assessed from sustained load.

**Read-only diagnostics (about 17:45).**

- The machine is a virtual machine with 8 processors (Intel Xeon Platinum 8581C, 2.3 GHz). Its cgroup allows all 8
  and has never throttled it. Nothing else was using the processor.
- The 8 processors come in 4 pairs (0-1, 2-3, 4-5, 6-7) that share their L1 and L2 caches. The processors report the
  "ht" flag, so each pair is most likely the two hyperthreads of one physical core, although the machine describes
  itself as 8 separate cores. Its scheduler does not know about the pairs, so it can put two busy workers on one pair
  even when other pairs are free. Seven workers always need at least three pairs to carry two workers each.
- Since the restart at 16:49, other users of the physical host took 973 of the 2,975 processor-seconds our processors
  asked for (33%), on all eight processors alike. The machine cannot see or control this.
- Each worker already uses a single thread for numerical libraries (the locked code sets this), so the workers do not
  start extra threads that would compete.

**The workload.** cause_sustained_bench.py (new; it changes no locked file) runs the locked base-run code on old start 1
only. That start's long run has been saved since Test 17. No new start or branch is run, and nothing the run computes
is kept. Several processes run it at once for up to 240 seconds, the way a base piece runs its base runs at once. The
script records how far each process gets every 50 time units, how much processor time it got, and the machine's busy,
idle and stolen time every 5 seconds. Only timings are written, to cause_operations_bench.json. Each trial is one
foreground command and ends by itself. The order of trials: 7 at once (the protocol as fixed), 4 at once with one per
cache pair, 4 at once placed by the scheduler, 1 alone, then 7 at once again to see whether the machine drifted.

A piece's time is judged as its slowest task. A base piece is one base run per worker; a moment task is six branches
of 500 time units at the slowest rate any worker had in any minute, plus 2 s. The 228-second target stays.

**Results (17:51 to 18:05).** Every trial ran the full base run (6,300 time units) to the end; none reached the cap.

| trial | each full base run | processor time per time unit | stolen | time units per second, all workers together |
| --- | --- | --- | --- | --- |
| 17:51, 7 at once | 150 to 153 s | 23.2 to 23.7 ms | 3% | 297 |
| 17:54, 4 at once, one per cache pair | 144 to 146 s | 22.4 to 22.8 ms | 2% | 177 |
| 17:57, 4 at once, placed by the scheduler | 146 to 150 s | 23.0 to 23.7 ms | 2% | 172 |
| 17:59, 1 alone | 133 s | 21.0 ms | 1% | 47 |
| 18:02, 7 at once again | 140 to 147 s | 22.1 to 23.2 ms | 3% | 310 |
| for comparison: piece 1 at 17:27, 7 at once | 227 to 267 s | | | |

**Findings.**

- **The slowdown came from the host, not from running seven at once.** Seven at once now take 140 to 153 s for the
  same base run that took 227 to 267 s in piece 1, with 1 to 3% of processor time stolen. From the restart at 16:49 to
  about 17:45, a stretch that includes piece 1, a third was stolen. At the processor time the work needs now, piece
  1's tasks spent 35 to 45% of their time waiting, which matches. During the slow spell (16:57 to 17:15), the check
  run alone was slowed about as much as piece 1's seven tasks.
- **Running fewer at once would not help.** With the host quiet, a base run takes 133 s alone, 144 to 150 s with four
  at once and 140 to 153 s with seven. Seven at once cost each run 5 to 15% over running alone, but get through 6.3 to
  6.5 times the work of one and 1.7 to 1.8 times the work of four. Keeping workers on separate cache pairs made no
  difference that matters (144 to 146 s against 146 to 150 s). With the host busy, even one process alone ran 1.6 to
  2.2 times as slowly, so fewer at once would not have brought a piece inside the target either.
- **No amendment is needed, and none is proposed.** The protocol as fixed (7 workers; 7 base runs or 14 moment tasks
  per piece) fits the target when the host is quiet. A base piece takes about 147 to 153 s and a moment piece about
  146 to 156 s (two rounds of 73 to 78 s), against 228 s.
- **When the host is busy, no arrangement brings a base piece inside the target.** A base run is one task, and piece
  1 shows that it then takes about 230 to 270 s on its own. Moment tasks are shorter: at piece 1's slowdown a moment
  piece of two rounds would take about 220 to 280 s, close to the limit, while one round (7 moment tasks) would take
  about 110 to 140 s. Pieces of 7 moment tasks would be an operational amendment and are not made without Colson's
  approval.

**The rule proposed from here (the 285-second limit and the 228-second target unchanged).** Pieces run one at a time, as fixed.
If a piece takes longer than 228 s or is cut off, the run pauses. It resumes only when this sustained workload, seven
full base runs on old start 1 at once, finishes in 228 s or less. The short check is no longer used to judge speed.

**18:06: still paused, ready to resume.** Piece 1's seven parts match their SHA-256 in the run log, no other file is
in cause_parts, and the lock's 16 fingerprints and the settings match. No trial changed the run log. The findings go to
Colson, and the run stays paused until he decides. If he says to go on, one more sustained check (seven full base runs
on old start 1 at once) runs first, and piece 2 starts only if it finishes in 228 s or less.

**Colson's decision (about 18:15): resume with the original locked protocol, unchanged.** In his words: "Run the final
sustained, full-length benchmark. Proceed to piece 2 only if the benchmark completes within 228 seconds. Maintain the
original seven-worker execution, 285-second hard limit, and 228-second safety target. If any production piece exceeds
228 seconds, pause again immediately after preserving its completed outputs and recording the timing. Do not modify
any locked files, random seeds, model parameters, decision criteria, or previously completed results. Keep
operational diagnostics separate from scientific outcomes. No publication or website changes. Authorized to resume
under these conditions." The 7-task moment pieces were not chosen; pieces stay 7 base runs or 14 moment tasks.

**18:19 to 18:23: the final sustained check did not pass, so piece 2 was not started.** Seven full base runs on old
start 1 ran at once. Six finished in 228 to 238 s. The seventh reached the 240-second cap at t = 5,800 of 6,000; it
would have needed about 249 s. Only 4% of processor time was stolen this time, but each unit of work took 36 to 40 ms
of processor time, against 22 to 24 ms at 17:51 and 18:02. This slowdown showed up as slower processors, not as stolen
time. Nothing else was running on the machine: at 18:24 it was 99% idle.

**18:24 to 18:27: one run alone, as a diagnostic (outcome-free, like the trials).** It took 159 s (24.9 ms per unit),
against 133 s (21.0 ms) at 17:59. That is about 20% slower than in the quiet spell, while seven at once had been about
60% slower per unit. The two were measured five minutes apart, so the host may have changed in between. The earlier
finding that fewer workers would not help was measured while the host was quiet, and holds only for that. In a slow
spell like this one, seven at once may cost more. That has not been tested. Any change of workers or piece size
remains an amendment for Colson to approve.

**18:28: paused.** 7 of 462 tasks are done. The next piece would be the base runs for starts 26 to 32. The lock, the
settings, the run log and piece 1's parts are unchanged; no trial touched the run log. Colson is asked how to go on.

**Colson's decision (about 18:40): re-check every 10 minutes for up to an hour, protocol unchanged.** In his words:
"Re-check performance every 10 minutes for up to one hour using the representative full-length benchmark. Resume the
original locked protocol only if a check finishes within 228 seconds. Keep the 285-second hard limit and 228-second
operational target unchanged. If any completed production piece exceeds the target, pause again. Preserve all
completed tasks, frozen files, fingerprints, and scientific decision criteria. If the machine remains slow after one
hour, stop checking and leave the experiment safely paused for a fresh authorization. No changes to the website or
publication. The goal is reliable execution, not forcing a completion time." And: "a benchmark passing doesn't
guarantee the next piece will finish quickly. The production-piece limit must remain independently enforced."

### The monitoring rule (set before measuring)

- **A check** is seven full base runs of the locked base-run code on old start 1 at once (`cause_sustained_bench.py 7
  240`), one foreground command under the same 285-second timeout. It passes only if all seven reach the end of the
  full base run before the 240-second cap and the slowest takes 228 s or less.
- **Checks start 10 minutes apart**, counted from the first: at most six in an hour. If none passes, checking stops
  after the sixth, and the run stays paused for a fresh authorization.
- **When a check passes,** pieces run one at a time, as fixed, each under `timeout -k 10 285`. Each piece is judged by
  its own time; a passed check does not excuse a slow piece. A piece that takes longer than 228 s or is cut off pauses
  the run at once. Its completed outputs are kept and its timing recorded, and a new window of checks begins as above
  (the option Colson chose: up to an hour per pause). A failed task also pauses the run; it goes to Colson, not to the
  checks.

**18:44 to 18:47: check 1 passed.** All seven full base runs finished, in 154 to 163 s; 3% of processor time was
stolen. The run resumes under the locked protocol, unchanged, with piece 2.

**18:47 to 19:47: pieces 2 to 24 ran, each inside the target.** The base runs finished with piece 6 (42 of 462 tasks
at 19:00). Moment pieces took 134 to 179 s; the table of piece times is added when the run is done.

**19:47: piece 25 was cut off, not by the time limit and not by slowness.** The command running it ended abnormally
from outside after about a minute and a half (the tool that runs commands failed); the piece's processes stopped with
it. Its first round, seven moment tasks (moment_44_03 to moment_44_09), finished in 68 to 71 s and is logged with its
parts. The second round (moment_44_10 and moment_45_01 to moment_45_06) was lost; the protocol runs any unfinished
task again in the next piece. 301 of 462 tasks are done, and the 301 parts in cause_parts are exactly the logged ones.
The machine had not restarted, and memory was ample (12 GB available). As the monitoring rule says for a cut-off
piece, the run pauses and a new window of checks begins.

**19:49 to 19:52: check 1 of the new window passed.** All seven full base runs finished, in 147 to 150 s; 3% of
processor time was stolen. The run resumes, unchanged, with piece 26.

**19:52 to 19:57: pieces 26 and 27 ran inside the target** (155 s and 139 s).

**19:57: piece 28 was cut off the same way as piece 25.** The command running it ended abnormally from outside after
about a minute and a half. Its first round, seven moment tasks, finished in 62 to 66 s and is logged; the second
round was lost and runs again in the next piece. 336 of 462 tasks are done, and the parts in cause_parts are exactly
the logged ones. Both cut-offs came just after a piece's first round finished, with the machine fast. The system
recorded no out-of-memory events and no process-limit events, so the cause lies in the tool that runs commands, not in
the run. As the monitoring rule says, the run pauses and a new window of checks begins.

**20:00 to 20:03: check 1 of the new window passed.** All seven full base runs finished, in 159 to 166 s; 3% of
processor time was stolen. The run resumes, unchanged, with piece 29.

**20:00 to 20:25: pieces 29 to 37 ran inside the target** (134 to 148 s). All 462 tasks were done at 20:25. Over the
whole run, no piece that finished took longer than the 228-second target except piece 1 (267 s, before the pause), and
no task failed.

**20:26: the report ran** (`python3 -B cause_test.py report`, about 30 s). As the plan says, it checked every part
against its SHA-256 in the run log, assembled sim_cause4000.npz, checked the saved file against what was assembled,
removed cause_parts, and wrote cause_test.txt, cause_test.json and screenshots/nudge-test-cause-test.png. The report
lists no deviations from the plan, and the lock and its fingerprints were still unchanged afterwards. The result is
in those files, not in this log.

### Piece times

These run from the run log's stamps, which are whole seconds, so they differ by about a second from the times the
pieces printed.

| piece | began | kind | tasks done | each task (s) | piece (s, from the run log's stamps) |
| --- | --- | --- | --- | --- | --- |
| 1 | 17:27 | base | 7 of 7 | 227 to 267 | 267 |
| 2 | 18:47 | base | 7 of 7 | 144 to 149 | 150 |
| 3 | 18:49 | base | 7 of 7 | 150 to 157 | 157 |
| 4 | 18:52 | base | 7 of 7 | 158 to 163 | 162 |
| 5 | 18:55 | base | 7 of 7 | 152 to 156 | 156 |
| 6 | 18:58 | base | 7 of 7 | 146 to 151 | 151 |
| 7 | 19:00 | moment | 14 of 14 | 74 to 89 | 172 |
| 8 | 19:03 | moment | 14 of 14 | 79 to 96 | 180 |
| 9 | 19:07 | moment | 14 of 14 | 69 to 78 | 149 |
| 10 | 19:09 | moment | 14 of 14 | 65 to 69 | 138 |
| 11 | 19:11 | moment | 14 of 14 | 63 to 70 | 135 |
| 12 | 19:14 | moment | 14 of 14 | 69 to 81 | 153 |
| 13 | 19:17 | moment | 14 of 14 | 66 to 71 | 140 |
| 14 | 19:19 | moment | 14 of 14 | 70 to 73 | 144 |
| 15 | 19:21 | moment | 14 of 14 | 72 to 76 | 150 |
| 16 | 19:24 | moment | 14 of 14 | 65 to 74 | 143 |
| 17 | 19:27 | moment | 14 of 14 | 65 to 70 | 139 |
| 18 | 19:29 | moment | 14 of 14 | 66 to 70 | 138 |
| 19 | 19:32 | moment | 14 of 14 | 67 to 72 | 141 |
| 20 | 19:34 | moment | 14 of 14 | 70 to 77 | 148 |
| 21 | 19:37 | moment | 14 of 14 | 65 to 72 | 141 |
| 22 | 19:39 | moment | 14 of 14 | 66 to 71 | 140 |
| 23 | 19:42 | moment | 14 of 14 | 66 to 71 | 139 |
| 24 | 19:44 | moment | 14 of 14 | 63 to 69 | 135 |
| 25 | 19:47 | moment | 7 of 14 | 68 to 71 | cut off |
| 26 | 19:52 | moment | 14 of 14 | 70 to 83 | 155 |
| 27 | 19:55 | moment | 14 of 14 | 65 to 72 | 139 |
| 28 | 19:57 | moment | 7 of 14 | 62 to 66 | cut off |
| 29 | 20:03 | moment | 14 of 14 | 68 to 73 | 143 |
| 30 | 20:06 | moment | 14 of 14 | 65 to 68 | 135 |
| 31 | 20:08 | moment | 14 of 14 | 63 to 67 | 135 |
| 32 | 20:10 | moment | 14 of 14 | 67 to 71 | 140 |
| 33 | 20:13 | moment | 14 of 14 | 65 to 70 | 140 |
| 34 | 20:15 | moment | 14 of 14 | 68 to 78 | 148 |
| 35 | 20:18 | moment | 14 of 14 | 65 to 68 | 135 |
| 36 | 20:20 | moment | 14 of 14 | 65 to 70 | 137 |
| 37 | 20:22 | moment | 14 of 14 | 66 to 73 | 142 |