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).