docs/04-run-log.md

# 04 — Run log and the multi-week schedule

> Phase 4's plan is written **before** launch (MASTER_PROMPT §5: "If the estimated finish exceeds the
> week's remaining hours, plan the multi-week resume explicitly"). Numbers come from
> `docs/00-platform-notes.md` §9 and `memory/QUOTA.md`; nothing here is a guess dressed as a fact.

## 1. The arithmetic

**Amended 2026-09-19 after D-011.** The first version of this section planned against 11,062 tok/s, which
came from p0c's raw training loop at seq 1024 on a 113M model. Gate 3's P2 measured the real thing — the
frozen 106M shape, inside `Trainer`, fp16 + DDP on 2×T4 — and the honest numbers are ~30 % of that at
seq 2048 and ~7.7k at seq 1024. Everything below divides by a *measured* number, and the one row that is
still provisional is marked as such.

| Quantity | Value | Source |
|---|---|---|
| Tokens to train | 1,000,000,000 (fallback 900M) | frozen, `01-plan.md` §4 |
| Tokens per step | 262,144 = 4 × 1024 × 32 accum × 2 cards | frozen (D-011; unchanged in tokens) |
| Steps | **3,814** = `int(1_000_000_000 / 262_144)` | the trainer's own integer division, so the plan and the code cannot disagree |
| Tokens actually consumed at that horizon | **999,817,216** = 99.98 % of the 1.0 B target | 3,814 × 262,144 — reported as the achieved figure, never rounded up to "1 B" |
| Checkpoint interval | 381 steps = 99,876,864 tokens ≈ **3.6 h** at the planning rate | §2's one-per-10 % cadence; `--stop-after-steps` must be a whole multiple of it |
| Throughput, seq 2048 (the old plan-of-record) | 4,071 tok/s, peak 14.22 GB → **68.2 h** | P2, ledger row 11 |
| Throughput, seq 1024 eager m4 (no ckpt) | 7,732 tok/s, peak 12.25 GB → **35.9 h** | A/B v2, row 13b |
| Throughput, seq 1024 eager+GC m8 | 7,828 tok/s, peak 7.12 GB → **35.5 h** | A/B v3, row 14 |
| **Throughput at the frozen geometry (m4 + grad-ckpt, seq 1024, accum 32)** | **9,358 tok/s measured across three legs (9,518 / 9,466 / 9,358), peak 5.99 GB → 29.68 h** | **P3 v3, ledger row 16. Supersedes the 35.5-35.9 h estimate: those came from cells run at `--accum 1`.** `--stage opts` (row 17) is measuring whether the headroom this reveals buys more |
| Planning rate | **7,732 tok/s → 35.9 h for 1 B** | the slower of the two seq-1024 cells; the m8 cell is not the frozen batch |
| GPU quota | 30 h/week, 2×T4, billed at **1× session wall-clock** | 5 GPU sessions; the 1× ratio confirmed on the 4 pairs where container time and quota delta were both read |
| Weekly reset | **Saturday 00:00 UTC** (next: 2026-09-26, then 2026-10-03) | `quota_refresh_time` |
| Checkpoint cycle cost | 26.3 s push+verify, 10.7 s cold pull (1.7 GB) | P1, row D-007 |
| Cold-start cost per interruption | ~4 min (image import, Hub pull, first step) | estimate, **P3 measures it** |

Two numbers decide the calendar. Total GPU need is **35.9 h** at the planning rate, and week 1's quota is
already **0.447 h** gone to Gate 3 with ~1 h more (P3) to spend, so **~28.5 h of week 1 is available to
the run and the remaining ~7.4 h lands in week 2**. That is the shape §5 asks to be planned explicitly:
one scheduled quota boundary mid-run, resumed from the Hub `latest`.

**When the pre-registered 0.9 B fallback fires.** Two weeks give 30 + 30 h; allow 6 h of that for
interruption overhead, the checkpoint cycles and Phase 6's GPU evals, so ~54 h is left for training. 1 B
tokens needs ≤54 h ⇒ **≥5,147 tok/s**. The planning rate is 50 % above that threshold, so the fallback
should not fire — but if P3's frozen-geometry rate comes in below ~5,100 tok/s, or if two consecutive
sessions sustain below it, the token target drops to 900 M **before** launch, per `01-plan.md` §4, and the
change is recorded here rather than improvised at 3 a.m.

## 2. The calendar

Written 2026-09-19, after Gate 3's non-GPU stages closed and before P3. Every row is a *budget*, not a
prediction; the log below this section is where reality gets recorded.

**Calendar note, checked against the platform:** `quota_refresh_time` = **2026-09-26T00:00:00Z**, exactly
7 days from today, and today is therefore **Saturday 2026-09-19** — week 1 started at 00:00Z this morning.
Do not plan against a weekday that was assumed rather than looked up.

| Window | GPU h | Running total | What happens |
|---|---|---|---|
| Sat 19 (today) | 0.45 | 0.45 | **done:** P2 T1 cells + A/B v2 + A/B v3 (rows 10-14). Gate 2 closes on CPU, zero GPU |
| Sat 19 → Sun 20 | ~1.0 | ~1.5 | Preflight **P3** on the frozen config: three legs (20/40/60 steps), each resumed cold from the Hub after a disk wipe, real mix-v1 data, one checkpoint per leg. This is also the missing m4+grad-ckpt throughput cell |
| Sun 20 | 0.0 | — | **Gate 3 signed, config frozen, main run launched.** Expect a session of ~6-12 h; the GPU session cap is unmeasured and P3 reports its own incidentally |
| Sun 20 → Fri 25 | ~26 | ~27.5 | Main run, week 1. 26 h at 7,732 tok/s ≈ **722 M tokens** ⇒ checkpoints 10-70 %, plus `latest` |
| Sat 26 00:00Z | — | — | Quota resets (30 h). Resume from the Hub `latest` — planned, not an incident |
| Sat 26 → Sun 27 | ~10 | ~37.5 | Final ~280 M tokens: checkpoints 80-100 %. **Gate 4** |
| Mon 27 → Wed 29 | ≤1 | — | Phase 5 publish (CPU), Phase 6 benchmarks (8 tasks × 2 shot settings on one T4), Phase 7 report |

Slack: 60 h of two-week quota − 1.5 h preflight − 35.9 h training ≈ **22 h** for interruption overhead,
re-launches and GPU evaluation. The binding constraint is no longer the token budget; it is the **GPU
session wall-clock cap**, which is why the run is designed to survive an arbitrary number of kills rather
than to avoid them.

**Checkpoint cadence vs. sessions.** 10 checkpoints (one per 10 % = every 382 steps ≈ every 3.6 h) is
§2's requirement; `latest` rolls with each of them. A session that dies between checkpoints loses at most
3.6 h of work, and the 30 h/week boundary is crossed exactly once, on a date known in advance.

### 2.1 Revision at launch (2026-09-20 00:06Z)

Two of the numbers above are now measured rather than assumed, and one of them changed the schedule.

- **Interval length: 2.97 h at the planning rate, not 3.6 h.** The frozen geometry measured 9,358-9,696
  tok/s (P3). Planning uses the **lower** figure deliberately — it is the one that was measured on the real
  legs — so a 381-step interval is 99,876,864 / 9,358 = **2.97 h**, the run is 10 × 2.97 = **29.7 h**, and
  each session keeps 0.6 h of reserve on top.
- **The session cap is no longer unknown, and the idle time is not billed.** `p0e` has been alive on a CPU
  instance for **8.45 h** (15:38Z → 00:05Z), and GPU billing tracks the container's wall clock, not the
  timeout it was given: P3 was given a 4,320 s ceiling and was charged **1,609.956 s**. A session therefore
  ends when `phase4_session.py` exits, so planning a 6.9 h ceiling costs ~6.5 h and leaves no paid idle
  time — the cap sets the *maximum*, the checkpoint grid sets the *actual*.
- **Resulting schedule: five sessions of two intervals each.** `SESSION_GPU_HOURS=6.9`,
  `PLANNING_TOK_PER_S=9358` → 6.3 usable hours → the planner takes 2 of the 2.97 h intervals → steps
  0→762→1,524→2,286→3,048→3,814. Billed ≈ 6.5 h × 5 = **32.5 h** against **27.50 h left this week**
  (quota at 00:03Z: 9,005.268 s = 2.501 h of
  30 h) and a reset at 2026-09-26T00:00Z. Sessions therefore end at 20 %, 40 %, 60 %, 80 % and 100 % of
  the run, and the 10 %, 30 %, 50 %, 70 % and 90 % marks fall mid-session — all ten are pushed, because the
  push cadence is the trainer's own 381-step grid and not the session's, and `latest` rolls with each one.
- Slack after revision: 60 h of two-week quota − 2.5 h preflight − 32.5 h training ≈ **25 h** for
  re-launches, evaluation and the overhead of five cold resumes.


## 3. Interruption model

The run will be interrupted by things outside the project's control. Each one is handled the same way:
`latest` on the Hub is the only truth, a new session pulls it, checks the cursor, and continues.

| Cause | Expected frequency | Cost | Mitigation |
|---|---|---|---|
| Session wall-clock cap | unknown; **≥3.9 h proven for CPU** (p0e still alive at 19:29Z, 3 h 51 m in), GPU cap unmeasured | ~4 min cold start | `--resume auto`; roll `latest` every 10 %, and freely if a session looks long. P3's GPU session measures the cap incidentally |
| Quota boundary | 1 per week, scheduled | one cold start | plan the boundary, do not discover it |
| Disk pressure | avoidable | run failure | §3.13 cycle every checkpoint, free space logged beside loss |
| Preemption / Kaggle fault | unknown | one checkpoint of lost work at worst | rolling `latest` after every 10 % ⇒ ≤10 % of tokens re-run |
| Loss anomaly | unknown | investigation | §3: never fix by changing config; document in this file and keep going |

**The rule that keeps this honest:** after checkpoint 1 exists, restarting the run is forbidden (§3.1). If
a bug is found mid-run that touches the loss landscape, the run continues and the finding goes in §5
below as a limitation of the reported result — not as a restart.

## 4. Run log

_Append only: one row per session, with step, tokens, loss, free GB, and what was done._

| Date (Z) | Event | Step | Tokens | Loss | Free GB | Notes |
|---|---|---|---|---|---|---|
| 09-20 11:13 | **session 1 started** | 0 | 0 | — | 19.5 | `ounce100m-p4-session1`, launcher @ `c237b478`; config frozen at D-018 **before** any run checkpoint existed, so §3.1's no-restart rule was never in tension. Resume branch: `Cion-lab/ounce100m-ckpt` absent → RepoMissing → step 0 |
| 09-20 11:14 | repo created | — | — | — | — | `initial commit` in `Cion-lab/ounce100m-ckpt`, i.e. the disk/pointer/mix gates all passed |
| 09-20 11:59 | **checkpoint 127 on the Hub** | 127 | 33,292,288 | 7.1317 (mean of steps 101-120) | see note | `ckpt/checkpoint-127`, 11 files / 1,274,563,198 B; pointer rolled 7 s later and read back. Cursor verified anonymously: `samples_consumed 32,512 = 127 × 256`, `shuffle_perm_sha c6f617b96f502d96` identical to the probes' for the same seed and window count, `dataset_files_sha 53df4708526da5c8` = the published mix. LR finished its 100-step warmup at 6e-4 and grad_norm stayed 0.25-0.52 |
| 09-20 12:45 | **checkpoint 254 on the Hub** | 254 | 66,584,576 | 6.4678 (mean of 221-240) | — | 127→254 in 45 min 30 s = **21.5 s/step**, the soak's rate holding; cursor 65,024 samples = 254 × 256, `shuffle_perm_sha` unchanged, LR on its 6e-4 plateau, grad_norm 0.49-0.66. Session 1's remaining 508 steps project to ≈15:50Z |
| 09-20 13:30 | **checkpoint 381 — 10 % of the run** | 381 | 99,876,864 | 5.9815 (mean of 361-380) | — | third interval, 45 min 30 s after the second, so **21.5 s/step holding exactly**; pointer rolled 10 s later; loss monotone across 340/360/380 (6.081 → 6.051 → 5.981), grad_norm 0.52-0.83, LR still on its 6e-4 plateau. §3's loss-monitoring check: nothing anomalous to investigate |
| 09-20 13:48 | independent re-read of all three checkpoints | 381 | 99,876,864 | — | — | anonymous `resolve` fetch from this workspace, not from the job: `latest.json` step 381 / tokens 99,876,864 / samples 97,536; `381 × 262,144 == tokens_consumed` exactly and `381 × 256 == samples_consumed`; `dataset_files_sha` and `shuffle_perm_sha` identical across 127/254/381 and to the probe records; 11 files and 1,273 MB per step confirmed in the remote tree. Recorded in `ASSETS.md` §Checkpoints, which was still empty until this row |
| 09-20 15:48 | **session 1 boundary — 20 % of the run** | 762 | 199,753,728 | 5.2030 (step 760) | see note | `-508` 14:16:36, `-635` 15:02:21, `-762` 15:48:06, pointers 7-9 s later. Legs 45m47s / 45m45s / 45m45s. Session exited ≈15:48:20Z, established from the billing delta (6,976 s accrued across 7,632 s of wall clock) because no kernel log exists before completion. **4.60 h billed** |
| 09-20 20:28 | **session 2 boundary — 40 %; the run-scale cold-resume proof** | 1,524 | 399,507,456 | 4.6957 (step 1,520) | — | launched 16:01:59Z, `QUOTA_LEFT_HOURS="20.3"`. Resumed from `latest.json` on a *different instance* and the first boundary cursor read back `step 889 / 233,046,016 tokens / 227,584 samples`, both fingerprints unchanged from session 1, seed 20260919 — with loss continuous 5.2030 → 5.0433 across the process death. Legs 43m53s-44m40s, i.e. faster than session 1. **4.445 h billed** |
| 09-21 00:57 | **session 3 boundary — 60 %** | 2,286 | 599,261,184 | 4.5204 (step 2,280) | — | launched 20:35:02Z. Six legs ~43m. `tokens == 2286 × 262,144` and `samples == 2286 × 256` exactly; fingerprints intact; grad_norm 0.22. **4.263 h billed** — the fastest session |
| 09-21 05:36 | **session 4 boundary — 80 %** | 3,048 | 799,014,912 | 4.4319 (step 3,040) | — | launched 01:03:37Z. Legs returned to ~45m (`-2,413` 01:50:22 · `-2,540` 02:35:26 · `-2,794` 04:05:45 · `-2,921` 04:50:55 · `-3,048` 05:35:54). **4.53 h billed**. ⚠ Then ~2.9 h idle before session 5 (E-052): the wake-up lived only in a background waiter that did not survive a context break. No work or quota lost; the finish moved ~3 h later and `NEXT CHECK` is now written into `STATE.md` on every leg |
| 09-21 08:31 | **session 5 launched — the final session** | 3,048 → 3,814 | → 999,817,216 | — | — | `ounce100m-p4-session5` v1, kernel 135209858, `QUOTA_LEFT_HOURS="7.0"` from the 08:29Z live read (82,755 s of 108,000). Alive confirmed by billing (+419 s in 521 s). 766 steps ⇒ **horizon ≈13:07Z**, then Phase 5 on CPU (0 h) and Phase 6 with the ~2.3 h that remains |
| 09-21 13:09 | **HORIZON REACHED — Gate 4 signed** | 3,814 | **999,817,216 = 100 %** | **4.2647** (step 3,800); `final_loss 4.264702` | — | `-3,556` 11:37:08 · `-3,683` 12:22:28 · `-3,810` 13:07:36 · `-3,814` 13:09:25 · `checkpoint final` 13:10:39, pointers 6-9 s behind each. Cursor `samples 976,384 == 3,814 × 256`, both fingerprints unchanged from session 1; grad_norm 0.18, LR decayed to 1.18e-5 on the trapezoid tail. **Held-out `val/` PPL 75.9825** over 1,953 windows, `val_skipped false`. Billed 4.59 h; whole run **22.43 h of 30** |
| 09-21 13:55 | **Phase 5 — model published, Gate 5 signed (0 GPU-h)** | — | — | — | — | `Cion-lab/ounce100m-v1`, 11 files, all 8 uploaded files re-hashed anonymously (`published_verified true`, `missing []`); clean-room load on a fresh instance with every token var popped → `load_ok=True generate_ok=True tied_ok=True vocab=49152`. Three publisher defects fixed by running it: E-054 `max_workers`, E-055 shadowed `shutil` + bare `tokenizer.json` |
| 09-21 14:13 | **Phase 6 STOPPED by the owner — no benchmark rows exist** | — | — | — | — | The single eval launcher died at 1.77 s on E-056 (`ModuleNotFoundError: ounce100m_credentials`, a missing `sys.path.insert` in my wrapper), ~8 s billed. Owner then directed "remove any benchmark phase... finalize it all". Gate 6 **unsigned**; `docs/final-report.md` §3 keeps the D-005 bands with "not run" beside them. Driver + frozen protocol remain in `ounce100m-code` for a future 2.35 h this week or after the 2026-09-26 reset (**D-020**) |

> **Why `Free GB` is `—` for the mid-session rows:** §3.13 wants free space logged beside loss, and the trainer
> does print it at every cycle — but Kaggle exposes no kernel log until the session completes, so the number is
> not reachable while session 1 runs. It is **backfilled from the completed session log** at the next park
> rather than guessed from the probes. Stated here so the gap is a known limitation of this table, not an
> omission; the disk itself is not at risk (each cycle prunes 1.19 GiB the moment the bytes verify, and the
> run's own floor assertion refuses to start below 8 GB free).


### 4.1 Pre-run probe chain — signed 2026-09-20T09:42Z

`--stop-after-steps` is the mechanism every Phase 4 session ends on, and Gate 3 never exercised it (its legs
used `--max-steps`, so each leg *was* a whole run). Eight GPU attempts of `kernels/p4_stop_probe.py` in
smoke mode (20 steps at 262,144 tokens/step on the published mix) closed that gap. Final verdict:
**`VERDICT P4PROBE PASS [] seconds 578.0`, 16/16 checks, both legs exit 0.**

What the last successful pair demonstrated, in order: leg 1 trained to step 10 of 20, pushed
`ckpt/checkpoint-10`, Hub-verified it, rolled `latest.json` and read it back, pruned the local copy, and
exited 0 with `val_skipped: true`. The probe then deleted the local run directory, and leg 2 resumed from the
Hub alone (`auto-resume: hub says step 10`), continued to the horizon, pushed `ckpt/checkpoint-20` and
`final/`, ran the held-out validation pass, and rolled the pointer to `final` at step 20. Cursor and pointer
agree with the arithmetic at every boundary: 2,621,440 then 5,242,880 tokens = 10 and 20 × 262,144,
`samples_consumed` 2,560 → 5,120, `shuffle_perm_sha c6f617b96f502d96` and `dataset_files_sha
53df4708526da5c8` identical across the resume. Loss `10.7723 → 10.1926 → 9.5255` over steps 5/10/20;
`params 106,194,240`; `grad_ckpt false` confirmed from the artifact rather than the command line.

**Cost of the chain: 4,501.6 s (1.25 h) of the 6 h small-model cap.** What each attempt bought, in the order
it was learned: the interpreter passed to `torchrun` as the script (E-037); a stale-pointer refusal on a
dirty repo and a `delete_folder` argument order (E-038); a harness that could not read its own tee'd output
and a 797 s cold whole-object read-back inside checkpoint verification (E-041); the prune guard living only
inside the wrapper the save path bypasses (E-042); a failure printer that printed nothing (E-043); and the
actual crash — a rank-0-only assertion killing rank 1 on every forced-stop leg (E-044). Two of those were
latent defects in code that had already been reviewed twice, and one was a wrong diagnosis recorded as a
finding; none of them would have surfaced before a billed five-hour session.

Numbers carried into the freeze: checkpoint cycle (push + verify + pointer + read-back + prune) **14-17 s**
for 1.27 GB; step time **20.20 s** = 12,977 tok/s; memory **12.84 GiB reserved / 12.70 allocated** for the
leg that never evaluates, against 13.66 GiB once `evaluate()` has run — which is why the soak's gate is on
the training leg.

## 5. Deviations and limitations

_To be filled from the run itself. Anything a third party would need in order to reproduce the reported
numbers goes here, including the packing policy (D-008) and the exclusion of code (D-009)._