From f751d6ad2fce7cf11cf907efc9facf9288bb3cf4 Mon Sep 17 00:00:00 2001 From: Dmitrii Vasilev Date: Mon, 19 Oct 2026 11:34:39 +0700 Subject: [PATCH 1/4] wip(train_hslm): profile=1 times the parts of a training step Co-Authored-By: Claude Opus 5.5 --- specs/ml/train_hslm.t27 | 330 +++++++++++++++++++++++++++++++++++++++- 1 file changed, 326 insertions(+), 4 deletions(-) diff --git a/specs/ml/train_hslm.t27 b/specs/ml/train_hslm.t27 index 30ce0fb131..b699e4f92d 100644 --- a/specs/ml/train_hslm.t27 +++ b/specs/ml/train_hslm.t27 @@ -30,7 +30,8 @@ ; /tmp/hslm/train.cfg optional, key=value lines of integers: steps, total, warmup, ; eval_every, ckpt_every, seed, speed, resume, synth, eval_windows, ; loss_positions (1..27, default 27), gradcheck (1: print the -; gradient checks and exit) +; gradient checks and exit), profile (1: time the parts of every +; step and print them at the end; section 1 says how) ; /tmp/hslm/ckpt_.bin MSLH: nn/hslm_data's header (magic 0x484C534D, version 1, step, ; f32 loss = the last minibatch loss under the k-position ; objective) and its layout, f32: output shadow (243 x 729, @@ -275,16 +276,126 @@ var cfg_synth : u64 = 0; var cfg_eval_windows : u64 = DEFAULT_EVAL_WINDOWS; var cfg_loss_positions : u64 = DEFAULT_LOSS_POSITIONS; var cfg_gradcheck : u64 = 0; +var cfg_profile : u64 = 0; + +; THE PROFILE (profile=1 in train.cfg; gHashTag/t27#10823). Where a training step's time goes, read +; off the monotonic clock with interval attribution: every mark charges the time since the previous +; mark to one part. The four local kernels mark their own entry and exit, so a kernel's part holds +; exactly its calls; the gap before a kernel goes to the region the call order puts there. Forward, +; per position: Q K V O up down per block (calls 0..17), then the head (18); the gap before each O +; matmul (calls 3, 9, 15) is the attention core with RoPE. Backward, per position: the head's +; outer_add and t_add (calls 0, 1), then per block from the last: outer down, t_add down, outer up, +; t_add up, outer O, t_add O, outer Q K V, t_add Q K V (12 calls); the gap before outer Q (local +; call 6) is the attention core's backward with the inverse RoPE. Profile off costs one branch per +; kernel call and changes no bit (a test runs one step both ways and compares the parameters). +const PR_FWD_MM : usize = 0; +const PR_ATT_FWD : usize = 1; +const PR_FWD_OTHER : usize = 2; +const PR_BWD_TADD : usize = 3; +const PR_BWD_OUTER : usize = 4; +const PR_ATT_BWD : usize = 5; +const PR_BWD_OTHER : usize = 6; +const PR_LOSS : usize = 7; +const PR_ZERO : usize = 8; +const PR_GATHER_CLIP : usize = 9; +const PR_LAMB : usize = 10; +const PR_REQUANT : usize = 11; +const PR_STEP_OTHER : usize = 12; +const PR_PARTS : usize = 13; +const PR_FWD_CALLS : usize = 19; +const PR_CALIBRATE : usize = 1000000; +var prof_on : bool = false; +var prof_ns : [PR_PARTS]u64 = undefined; +var prof_calls : [PR_PARTS]u64 = undefined; +var prof_last : u64 = 0; +var prof_fcall : usize = 0; +var prof_bcall : usize = 0; +var prof_sink : u64 = 0; ; --------------------------------------------------------------------------------------------- ; 1. Kernels. The four names below are nn/hslm.t27's; a local declaration wins over the spliced ; one, also inside the spliced forward and backward. speed 0 runs nn/hslm.t27's code unchanged. ; --------------------------------------------------------------------------------------------- +/// The monotonic clock in ns +fn prof_now() -> u64 { + var ts: std.os.linux.timespec = undefined; + const rc = std.os.linux.clock_gettime(std.os.linux.CLOCK.MONOTONIC, &ts); + if (rc != 0) { + return prof_last; + } + return @as(u64, @intCast(ts.sec)) * 1000000000 + @as(u64, @intCast(ts.nsec)); +} + +fn prof_reset() -> void { + var i : usize = 0; + while (i < PR_PARTS) { + prof_ns[i] = 0; + prof_calls[i] = 0; + i = i + 1; + } + prof_fcall = 0; + prof_bcall = 0; +} + +/// Charge the time since the last mark to `part` +fn prof_mark(part: usize) -> void { + const now : u64 = prof_now(); + if (now >= prof_last) { + prof_ns[part] = prof_ns[part] + (now - prof_last); + } + prof_calls[part] = prof_calls[part] + 1; + prof_last = now; +} + +/// The part that owns the gap before forward kernel call `c` of a position +fn prof_fwd_gap_part(c: usize) -> usize { + if (c < 18 and c % 6 == 3) { + return PR_ATT_FWD; + } + return PR_FWD_OTHER; +} + +/// The part that owns the gap before backward kernel call `c` of a position +fn prof_bwd_gap_part(c: usize) -> usize { + if (c >= 2 and (c - 2) % 12 == 6) { + return PR_ATT_BWD; + } + return PR_BWD_OTHER; +} + +fn prof_fwd_enter() -> void { + prof_mark(prof_fwd_gap_part(prof_fcall)); +} + +fn prof_fwd_leave() -> void { + prof_mark(PR_FWD_MM); + prof_fcall = prof_fcall + 1; +} + +fn prof_bwd_enter() -> void { + prof_mark(prof_bwd_gap_part(prof_bcall)); +} + +fn prof_bwd_leave(part: usize) -> void { + prof_mark(part); + prof_bcall = prof_bcall + 1; +} + /// output[i] = sum_j input[j] * w[j * out_dim + i]. Speed 0: nn/hslm.t27's branchy dot per output. /// Otherwise: zero the output, then add x_j * trit row by row (an axpy the compiler vectorizes); /// per output the terms are added in the same order j = 0, 1, ..., so the result is the same bits. fn ternary_matmul(input: []const f64, weights: []const Trit, output: []f64, in_dim: usize, out_dim: usize) -> void { + if (prof_on) { + prof_fwd_enter(); + } + tr_matmul_fast(input, weights, output, in_dim, out_dim); + if (prof_on) { + prof_fwd_leave(); + } +} + +fn tr_matmul_fast(input: []const f64, weights: []const Trit, output: []f64, in_dim: usize, out_dim: usize) -> void { if (speed_level == 0) { tr_matmul_ref(input, weights, output, in_dim, out_dim); return; @@ -333,6 +444,16 @@ fn tr_matmul_ref(input: []const f64, weights: []const Trit, output: []f64, in_di /// dx[j] += sum_i w[j * out_dim + i] * dy[i]. Speed 0: nn/hslm.t27's branchy sum. Otherwise four /// partial sums of trit * dy (the only kernel whose rounding differs from the reference). fn ternary_matmul_t_add(dy: []const f64, weights: []const Trit, dx: []f64, in_dim: usize, out_dim: usize) -> void { + if (prof_on) { + prof_bwd_enter(); + } + tr_t_add_fast(dy, weights, dx, in_dim, out_dim); + if (prof_on) { + prof_bwd_leave(PR_BWD_TADD); + } +} + +fn tr_t_add_fast(dy: []const f64, weights: []const Trit, dx: []f64, in_dim: usize, out_dim: usize) -> void { var j : usize = 0; while (j < in_dim) { const row : usize = j * out_dim; @@ -380,6 +501,16 @@ fn ternary_matmul_t_add(dy: []const f64, weights: []const Trit, dx: []f64, in_di /// gw[j * out_dim + i] += x[j] * dy[i], with x[j] read once per row; above speed 0 a row whose /// x[j] is 0 (half the ReLU outputs) is skipped, which adds nothing either way fn outer_add(x: []const f64, dy: []const f64, gw: []f64, in_dim: usize, out_dim: usize) -> void { + if (prof_on) { + prof_bwd_enter(); + } + tr_outer_add_fast(x, dy, gw, in_dim, out_dim); + if (prof_on) { + prof_bwd_leave(PR_BWD_OUTER); + } +} + +fn tr_outer_add_fast(x: []const f64, dy: []const f64, gw: []f64, in_dim: usize, out_dim: usize) -> void { var j : usize = 0; while (j < in_dim) { const xj : f64 = x[j]; @@ -504,7 +635,11 @@ fn tr_window_grad_k(tokens: []const u16, start: usize, k: usize) -> f64 { while (p < CONTEXT_LEN) { const tok : usize = @intCast(tokens[start + p]); if (p + k >= CONTEXT_LEN) { + prof_fcall = 0; hslm_forward(tok, p, &win_logits); + if (prof_on) { + prof_mark(PR_FWD_OTHER); + } const target : usize = @intCast(tokens[start + p + 1]); sum = sum + cross_entropy(&win_logits, target); cross_entropy_backward(&win_logits, target, &win_dl); @@ -513,11 +648,24 @@ fn tr_window_grad_k(tokens: []const u16, start: usize, k: usize) -> f64 { win_dl[j] = win_dl[j] * inv_k; j = j + 1; } + if (prof_on) { + prof_mark(PR_LOSS); + } + prof_bcall = 0; hslm_backward(&win_dl, &win_gin); - } else if (speed_level < 2) { - hslm_forward(tok, p, &win_logits); + if (prof_on) { + prof_mark(PR_BWD_OTHER); + } } else { - tr_prefix_forward(tok, p); + prof_fcall = 0; + if (speed_level < 2) { + hslm_forward(tok, p, &win_logits); + } else { + tr_prefix_forward(tok, p); + } + if (prof_on) { + prof_mark(PR_FWD_OTHER); + } } p = p + 1; } @@ -1553,7 +1701,13 @@ fn tr_train_step(t: u64, batch: usize, lr_fixed: f64, fixed: bool) -> f64 { /// tr_train_step under the k-position objective: the same windows, averaging, clip, LAMB and /// requantize; each window's loss and gradient come from tr_window_grad_k fn tr_train_step_k(t: u64, batch: usize, lr_fixed: f64, fixed: bool, k: usize) -> f64 { + if (prof_on) { + prof_mark(PR_STEP_OTHER); + } zero_weight_gradients(); + if (prof_on) { + prof_mark(PR_ZERO); + } var loss_sum : f64 = 0.0; var wi : usize = 0; while (wi < batch) { @@ -1566,16 +1720,28 @@ fn tr_train_step_k(t: u64, batch: usize, lr_fixed: f64, fixed: bool, k: usize) - loss_sum = loss_sum + tr_window_grad_k(train_tok[0..ntrain], start, k); wi = wi + 1; } + if (prof_on) { + prof_mark(PR_STEP_OTHER); + } const inv : f64 = 1.0 / @as(f64, @floatFromInt(batch)); tr_gather(inv); last_gnorm = tr_clip_global(g_val[0..NPARAM], CLIP_NORM); + if (prof_on) { + prof_mark(PR_GATHER_CLIP); + } var lr : f64 = lr_fixed; if (lr <= 0.0) { lr = tr_lr_at(t, cfg_warmup, cfg_total); } last_lr = lr; tr_lamb(lr); + if (prof_on) { + prof_mark(PR_LAMB); + } tr_scatter_all(); + if (prof_on) { + prof_mark(PR_REQUANT); + } last_loss = loss_sum * inv; return last_loss; } @@ -1861,6 +2027,8 @@ fn tr_cfg_set(off: usize, len: usize, value: u64) -> void { } } else if (tr_key_is(off, len, "gradcheck")) { cfg_gradcheck = value; + } else if (tr_key_is(off, len, "profile")) { + cfg_profile = value; } } @@ -2464,9 +2632,15 @@ fn tr_main() -> i32 { var run_steps : u64 = 0; var first_loss : f64 = 0.0; var rc : i32 = RC_OK; + prof_reset(); while (rc == RC_OK and step < cfg_steps) { const t0 : f64 = tr_now(); + if (cfg_profile != 0) { + prof_on = true; + prof_last = prof_now(); + } const loss : f64 = tr_train_step_k(step, BATCH, 0.0, false, k_obj); + prof_on = false; const t1 : f64 = tr_now(); step = step + 1; train_secs = train_secs + (t1 - t0); @@ -2532,9 +2706,117 @@ fn tr_main() -> i32 { ln_str(" rc "); ln_u64(@intCast(rc)); ln_flush(); + if (cfg_profile != 0) { + tr_profile_lines(run_steps); + } return rc; } +fn prof_name(part: usize) -> []const u8 { + if (part == PR_FWD_MM) { + return "fwd_matmul"; + } else if (part == PR_ATT_FWD) { + return "attn_fwd_core"; + } else if (part == PR_FWD_OTHER) { + return "fwd_other"; + } else if (part == PR_BWD_TADD) { + return "bwd_matmul_t"; + } else if (part == PR_BWD_OUTER) { + return "bwd_outer"; + } else if (part == PR_ATT_BWD) { + return "attn_bwd_core"; + } else if (part == PR_BWD_OTHER) { + return "bwd_other"; + } else if (part == PR_LOSS) { + return "loss"; + } else if (part == PR_ZERO) { + return "zero_grad"; + } else if (part == PR_GATHER_CLIP) { + return "gather_clip"; + } else if (part == PR_LAMB) { + return "lamb"; + } else if (part == PR_REQUANT) { + return "requantize"; + } + return "step_other"; +} + +/// The profile: per part the raw ns and the number of marks charged to it, then the cost of +/// one clock read, measured over PR_CALIBRATE back-to-back reads (in ps) +fn tr_profile_lines(steps: u64) -> void { + var total : u64 = 0; + var reads : u64 = 0; + var part : usize = 0; + while (part < PR_PARTS) { + ln_reset(); + ln_str("profile part "); + ln_str(prof_name(part)); + ln_str(" ns "); + ln_u64(prof_ns[part]); + ln_str(" marks "); + ln_u64(prof_calls[part]); + ln_flush(); + total = total + prof_ns[part]; + reads = reads + prof_calls[part]; + part = part + 1; + } + const c0 : u64 = prof_now(); + var i : usize = 0; + while (i < PR_CALIBRATE) { + prof_sink = prof_now(); + i = i + 1; + } + const c1 : u64 = prof_now(); + ln_reset(); + ln_str("profile steps "); + ln_u64(steps); + ln_str(" total_ns "); + ln_u64(total); + ln_str(" marks "); + ln_u64(reads); + ln_str(" ps_per_read "); + ln_u64((c1 - c0) * 1000 / @as(u64, PR_CALIBRATE)); + ln_flush(); +} + +/// One fixed k = 27 step on the tiny slice with the profile on or off; a digest of every parameter +/// bit afterwards (the profile must not move a bit) +fn tr_prof_step_digest(on: bool) -> u64 { + speed_level = 2; + tr_tiny_setup(11); + fixed_starts[0] = 300; + fixed_starts[1] = 1700; + prof_reset(); + prof_on = on; + prof_last = prof_now(); + const seen : f64 = tr_train_step_k(0, 2, 0.01, true, CONTEXT_LEN); + prof_on = false; + var h : u64 = 1469598103; + var i : usize = 0; + while (i < NPARAM) { + h = (h * 31 + (@as(u64, @bitCast(p_val[i])) % 4294967291)) % 4294967291; + i = i + 1; + } + if (seen != seen) { + return 0; + } + return h; +} + +/// The digest of a step with the profile off, then with it on +fn tr_prof_digest_off() -> u64 { + return tr_prof_step_digest(false); +} + +fn tr_prof_digest_on() -> u64 { + return tr_prof_step_digest(true); +} + +/// After tr_prof_digest_on: the marks charged to `part` (2 windows x 27 positions) +fn tr_prof_marks(part: usize) -> u64 { + return prof_calls[part]; +} + /// The program `t27c compile --backend ml` builds: train, evaluate, checkpoint; any checkpoint /// that does not read back byte-equal, a NaN loss or missing tokens fail the run pub fn main() -> void { @@ -3473,3 +3755,43 @@ test the_27_position_gradient_of_deep_parameters_matches_stop_gradient_differenc and mag_u > 1e-7 and rel_e < 1e-4 and mag_e > 1e-7 + +test the_profile_charges_attention_to_the_gap_before_the_o_matmul + given f3 = prof_fwd_gap_part(3) + and f9 = prof_fwd_gap_part(9) + and f15 = prof_fwd_gap_part(15) + and f2 = prof_fwd_gap_part(2) + and f18 = prof_fwd_gap_part(18) + and b8 = prof_bwd_gap_part(8) + and b20 = prof_bwd_gap_part(20) + and b32 = prof_bwd_gap_part(32) + and b7 = prof_bwd_gap_part(7) + and b0 = prof_bwd_gap_part(0) + then f3 == PR_ATT_FWD + and f9 == PR_ATT_FWD + and f15 == PR_ATT_FWD + and f2 == PR_FWD_OTHER + and f18 == PR_FWD_OTHER + and b8 == PR_ATT_BWD + and b20 == PR_ATT_BWD + and b32 == PR_ATT_BWD + and b7 == PR_BWD_OTHER + and b0 == PR_BWD_OTHER + +test the_profile_moves_no_bit_and_sees_the_call_order + given off = tr_prof_digest_off() + and on = tr_prof_digest_on() + and mm = tr_prof_marks(PR_FWD_MM) + and ta = tr_prof_marks(PR_BWD_TADD) + and ou = tr_prof_marks(PR_BWD_OUTER) + and af = tr_prof_marks(PR_ATT_FWD) + and ab = tr_prof_marks(PR_ATT_BWD) + and la = tr_prof_marks(PR_LAMB) + then off == on + and off != 0 + and mm == 1026 + and ta == 1026 + and ou == 1026 + and af == 162 + and ab == 162 + and la == 1 From 83fcc96026de0f9129436e816c0318d94246d71a Mon Sep 17 00:00:00 2001 From: Dmitrii Vasilev Date: Mon, 19 Oct 2026 11:36:29 +0700 Subject: [PATCH 2/4] wip(train_hslm): profile=2 reads the thread CPU clock Co-Authored-By: Claude Opus 5.5 --- specs/ml/train_hslm.t27 | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/specs/ml/train_hslm.t27 b/specs/ml/train_hslm.t27 index b699e4f92d..bba4de306f 100644 --- a/specs/ml/train_hslm.t27 +++ b/specs/ml/train_hslm.t27 @@ -278,9 +278,10 @@ var cfg_loss_positions : u64 = DEFAULT_LOSS_POSITIONS; var cfg_gradcheck : u64 = 0; var cfg_profile : u64 = 0; -; THE PROFILE (profile=1 in train.cfg; gHashTag/t27#10823). Where a training step's time goes, read -; off the monotonic clock with interval attribution: every mark charges the time since the previous -; mark to one part. The four local kernels mark their own entry and exit, so a kernel's part holds +; THE PROFILE (profile=1 or 2 in train.cfg; gHashTag/t27#10823). Where a training step's time goes, +; read off the monotonic clock (1) or the thread's CPU clock (2) with interval attribution: every +; mark charges the time since the previous mark to one part. The four local kernels mark their own +; entry and exit, so a kernel's part holds ; exactly its calls; the gap before a kernel goes to the region the call order puts there. Forward, ; per position: Q K V O up down per block (calls 0..17), then the head (18); the gap before each O ; matmul (calls 3, 9, 15) is the attention core with RoPE. Backward, per position: the head's @@ -311,16 +312,22 @@ var prof_last : u64 = 0; var prof_fcall : usize = 0; var prof_bcall : usize = 0; var prof_sink : u64 = 0; +var prof_cpu : bool = false; ; --------------------------------------------------------------------------------------------- ; 1. Kernels. The four names below are nn/hslm.t27's; a local declaration wins over the spliced ; one, also inside the spliced forward and backward. speed 0 runs nn/hslm.t27's code unchanged. ; --------------------------------------------------------------------------------------------- -/// The monotonic clock in ns +/// The monotonic clock in ns (profile=1), or this thread's CPU time (profile=2) fn prof_now() -> u64 { var ts: std.os.linux.timespec = undefined; - const rc = std.os.linux.clock_gettime(std.os.linux.CLOCK.MONOTONIC, &ts); + var rc : usize = 0; + if (prof_cpu) { + rc = std.os.linux.clock_gettime(std.os.linux.CLOCK.THREAD_CPUTIME_ID, &ts); + } else { + rc = std.os.linux.clock_gettime(std.os.linux.CLOCK.MONOTONIC, &ts); + } if (rc != 0) { return prof_last; } @@ -2633,6 +2640,7 @@ fn tr_main() -> i32 { var first_loss : f64 = 0.0; var rc : i32 = RC_OK; prof_reset(); + prof_cpu = cfg_profile == 2; while (rc == RC_OK and step < cfg_steps) { const t0 : f64 = tr_now(); if (cfg_profile != 0) { From 9432608170ea3e97dbd0c206c8da32884ec1caee Mon Sep 17 00:00:00 2001 From: Dmitrii Vasilev Date: Mon, 19 Oct 2026 11:50:24 +0700 Subject: [PATCH 3/4] wip(t27t): the t27c CPU runner, its measured split and four lever bounds (#10850) Co-Authored-By: Claude Opus 5.5 --- specs/ml/train_hslm.t27 | 2 +- specs/t27t/t27t.t27 | 357 +++++++++++++++++++++++++++++++++++++++- 2 files changed, 356 insertions(+), 3 deletions(-) diff --git a/specs/ml/train_hslm.t27 b/specs/ml/train_hslm.t27 index bba4de306f..8b52ec9f22 100644 --- a/specs/ml/train_hslm.t27 +++ b/specs/ml/train_hslm.t27 @@ -278,7 +278,7 @@ var cfg_loss_positions : u64 = DEFAULT_LOSS_POSITIONS; var cfg_gradcheck : u64 = 0; var cfg_profile : u64 = 0; -; THE PROFILE (profile=1 or 2 in train.cfg; gHashTag/t27#10823). Where a training step's time goes, +; THE PROFILE (profile=1 or 2 in train.cfg; gHashTag/t27#10850). Where a training step's time goes, ; read off the monotonic clock (1) or the thread's CPU clock (2) with interval attribution: every ; mark charges the time since the previous mark to one part. The four local kernels mark their own ; entry and exit, so a kernel's part holds diff --git a/specs/t27t/t27t.t27 b/specs/t27t/t27t.t27 index 35bd47b023..aabd125184 100644 --- a/specs/t27t/t27t.t27 +++ b/specs/t27t/t27t.t27 @@ -12,6 +12,11 @@ ; - Its second rule is the papers check (specs/numeric/paper_claims.t27, `tri papers`): a number ; t27t prints about its formats is one a spec can recompute. 45 printed numbers in three papers ; were recomputed: 34 fit, 8 do not, 3 cannot be checked. Those counts live in that spec, not here. +; - Its second runner is t27's own: the HSLM trainer specs/ml/train_hslm.t27 compiled by t27c +; --backend ml, on one CPU thread in f64 (gHashTag/t27#10850). Its profile says where a step goes: +; 94.2% in the three matmul kernels, 66.8% in the two backward ones, 42.4% in outer_add alone. +; Four levers are bounded from that split and not built; two of them need t27c support that +; --backend ml does not have. ; -- ; The rules of this file. ; - Times are in units of 10^-4 ms (0.2254 ms is 2254). Speed ratios are in hundredths (2.93x is 293). @@ -192,13 +197,266 @@ pub fn pick_path(pass: u32, has_int8_tc: bool, gen_vs_cutlass_e2: u64) -> u32 { return PATH_INT8_TC; } +// ---------------------------------------------------------------- the second runner: t27c on a CPU + +; The HSLM trainer specs/ml/train_hslm.t27, compiled by t27c --backend ml and Zig -O ReleaseFast, +; one thread, f64. Its profile (profile=1 or 2 in train.cfg, gHashTag/t27#10850) charges every +; interval between two clock reads to one of 13 parts. Measured on the Railway lab (48 cores, a +; shared host at load 56 to 86), 2026-10-19: 20 steps, speed 2, loss_positions 27, the tokens of +; /tmp/hslm. One step is 66 windows of 27 scored positions (1782 positions), and per position the +; model makes 19 matmul calls forward, 19 t_add and 19 outer_add calls backward. +; Times in this section are in ns, as the binary printed them. Shares are in tenths of a percent. +pub const CPU_RUNNER : str = "specs/ml/train_hslm.t27 via t27c --backend ml, Zig ReleaseFast, 1 thread, f64"; +pub const CPU_BENCH : str = "gHashTag/t27#10850: Railway lab, 48 cores, 20 steps, speed 2, loss_positions 27, 2026-10-19"; + +pub const CPU_PARTS : u32 = 13; +pub const CP_FWD_MM : u32 = 0; +pub const CP_ATT_FWD : u32 = 1; +pub const CP_FWD_OTHER : u32 = 2; +pub const CP_BWD_TADD : u32 = 3; +pub const CP_BWD_OUTER : u32 = 4; +pub const CP_ATT_BWD : u32 = 5; +pub const CP_BWD_OTHER : u32 = 6; +pub const CP_LOSS : u32 = 7; +pub const CP_ZERO : u32 = 8; +pub const CP_GATHER_CLIP : u32 = 9; +pub const CP_LAMB : u32 = 10; +pub const CP_REQUANT : u32 = 11; +pub const CP_STEP_OTHER : u32 = 12; + +pub const CPU_PART_NAME : [13]str = [ + "fwd_matmul", "attn_fwd_core", "fwd_other", "bwd_matmul_t", "bwd_outer", "attn_bwd_core", + "bwd_other", "loss", "zero_grad", "gather_clip", "lamb", "requantize", "step_other" +]; + +; profile=2: the thread's CPU clock, so time the host takes away from the trainer is not charged. +pub const CPU_NS : [13]u64 = [ + 34213431617, 1025430559, 2983795743, 30586403275, 52889511051, 1081772724, + 1186036579, 635887485, 68131696, 75441546, 348606165, 291810849, 21208 +]; +pub const CPU_MARKS : [13]u64 = [ + 677160, 106920, 605880, 677160, 677160, 106920, 1283040, 35640, 20, 20, 20, 20, 40 +]; +pub const CPU_TOTAL_NS : u64 = 125386280497; +pub const CPU_TOTAL_MARKS : u64 = 4170000; +; One read of the clock, in ps, timed by the binary over 10^6 reads (a system call for this clock). +pub const CPU_PS_PER_READ : u64 = 217564; + +; profile=1: the monotonic clock (a vDSO read), the wall-clock check of the same split. +pub const WALL_NS : [13]u64 = [ + 37866972295, 1072649017, 3200415034, 34393137429, 53616601587, 1207263330, + 778546683, 707573861, 96326500, 83721472, 391453562, 372297308, 11248 +]; +pub const WALL_TOTAL_NS : u64 = 133786969326; +pub const WALL_PS_PER_READ : u64 = 20857; +; The same run's train_s, in hundredths of a second. +pub const WALL_TRAIN_S_E2 : u64 = 13379; + +; s_per_step in units of 10^-4 s: profile 0, profile 2, profile 1. Each run is its own 20 steps +; on a shared host, so the three differ by the host's load as well as by the profile. +pub const S_PER_STEP_P0_E4 : u64 = 76935; +pub const S_PER_STEP_P2_E4 : u64 = 76970; +pub const S_PER_STEP_P1_E4 : u64 = 66895; +; profile 0: tok_per_s in tenths. +pub const TOK_PER_S_P0_E1 : u64 = 2316; +pub const CPU_STEPS : u64 = 20; +pub const WINDOWS : u64 = 66; +pub const SCORED_POSITIONS : u64 = 27; +pub const FWD_CALLS : u64 = 19; + +pub const CLOCK_CPU : u32 = 0; +pub const CLOCK_WALL : u32 = 1; + +pub fn raw_ns(clock: u32, i: u32) -> u64 { + if (clock == CLOCK_WALL) { return WALL_NS[i]; } + return CPU_NS[i]; +} + +/// A part's time less the clock reads charged to it (the marks are the same on both clocks). +pub fn net_ns(clock: u32, i: u32) -> u64 { + var ps : u64 = CPU_PS_PER_READ; + if (clock == CLOCK_WALL) { ps = WALL_PS_PER_READ; } + return raw_ns(clock, i) - CPU_MARKS[i] * ps / 1000; +} + +pub fn raw_sum(clock: u32) -> u64 { + var i : u32 = 0; + var s : u64 = 0; + while (i < CPU_PARTS) { + s = s + raw_ns(clock, i); + i = i + 1; + } + return s; +} + +pub fn marks_sum() -> u64 { + var i : u32 = 0; + var s : u64 = 0; + while (i < CPU_PARTS) { + s = s + CPU_MARKS[i]; + i = i + 1; + } + return s; +} + +pub fn net_total(clock: u32) -> u64 { + var i : u32 = 0; + var s : u64 = 0; + while (i < CPU_PARTS) { + s = s + net_ns(clock, i); + i = i + 1; + } + return s; +} + +/// part / total in tenths of a percent, rounded half up. +pub fn share_of(part: u64, total: u64) -> u64 { + return (2 * part * 1000 + total) / (2 * total); +} + +pub fn share_e3(clock: u32, i: u32) -> u64 { + return share_of(net_ns(clock, i), net_total(clock)); +} + +; The three matmul kernels of the step, and its serial tail: everything that runs once per step +; after the 66 windows (zero, gather and clip, LAMB, requantize, the rest). +pub fn matmul_ns(clock: u32) -> u64 { + return net_ns(clock, CP_FWD_MM) + net_ns(clock, CP_BWD_TADD) + net_ns(clock, CP_BWD_OUTER); +} + +pub fn bwd_matmul_ns(clock: u32) -> u64 { + return net_ns(clock, CP_BWD_TADD) + net_ns(clock, CP_BWD_OUTER); +} + +pub fn attention_ns(clock: u32) -> u64 { + return net_ns(clock, CP_ATT_FWD) + net_ns(clock, CP_ATT_BWD); +} + +pub fn serial_ns(clock: u32) -> u64 { + return net_ns(clock, CP_ZERO) + net_ns(clock, CP_GATHER_CLIP) + net_ns(clock, CP_LAMB) + + net_ns(clock, CP_REQUANT) + net_ns(clock, CP_STEP_OTHER); +} + +pub fn window_ns(clock: u32) -> u64 { + return net_total(clock) - serial_ns(clock); +} + +/// The part with the most time. +pub fn biggest_part(clock: u32) -> u32 { + var i : u32 = 1; + var b : u32 = 0; + while (i < CPU_PARTS) { + if (net_ns(clock, i) > net_ns(clock, b)) { b = i; } + i = i + 1; + } + return b; +} + +// ---------------------------------------------------------------- four levers, bounded, not built + +; Each bound is Amdahl's law on the CPU-clock split: a part of time f made x times faster leaves +; T - f + f / x. Bounds are speed-ups in hundredths, rounded half up. A bound is a ceiling the +; split allows, not a measured speed-up. +pub fn speedup_e2(total: u64, new_total: u64) -> u64 { + return (total * 200 + new_total) / (2 * new_total); +} + +pub fn amdahl_e2(f: u64, x_e2: u64) -> u64 { + var t : u64 = net_total(CLOCK_CPU); + return speedup_e2(t, t - f + f * 100 / x_e2); +} + +/// The part f removed outright: the ceiling of any lever on it. +pub fn without_e2(f: u64) -> u64 { + var t : u64 = net_total(CLOCK_CPU); + return speedup_e2(t, t - f); +} + +; (a) The 66 windows of a step on n threads, gradients summed in a fixed order: the windows take +; ceil(66 / n) rounds, the serial tail stays. The sum itself is not counted (NOT_MEASURED). +pub fn thread_bound_e2(n: u64) -> u64 { + var rounds : u64 = (WINDOWS + n - 1) / n; + var t : u64 = net_total(CLOCK_CPU); + return speedup_e2(t, serial_ns(CLOCK_CPU) + rounds * window_ns(CLOCK_CPU) / WINDOWS); +} + +/// The ceiling of (a) for any n: only the serial tail is left. +pub fn thread_limit_e2() -> u64 { + return speedup_e2(net_total(CLOCK_CPU), serial_ns(CLOCK_CPU)); +} + +; (b) f32 instead of f64: half the bytes and twice the SIMD lanes, so at most 2x on the matmul +; kernels, whose inner loops are f64 arrays. +pub const F32_X_E2 : u64 = 200; +; (c) One GEMM over the 27 positions of a window instead of a GEMV per position: each weight +; matrix (and each gradient matrix of outer_add) is read once per window instead of 27 times. +; The bound takes the matmul kernels to be weight-traffic bound, which is not measured. +pub const GEMM_X_E2 : u64 = 2700; +; (d) int8 activations against packed trits, forward only: 1 byte against 8 per operand. +pub const INT8_X_E2 : u64 = 800; + +pub const LEVERS : u32 = 4; +pub const LEVER_THREADS : u32 = 0; +pub const LEVER_F32 : u32 = 1; +pub const LEVER_GEMM : u32 = 2; +pub const LEVER_INT8 : u32 = 3; +; (a) is bounded at the lab's 48 cores. +pub const LAB_CORES : u64 = 48; + +pub const LEVER_NAME : [4]str = [ + "(a) 66 windows on N threads, fixed-order gradient sum", + "(b) f32 instead of f64", + "(c) one GEMM over 27 positions instead of a GEMV per position", + "(d) int8 activations against packed trits, forward" +]; + +; What t27c --backend ml lacks for a lever. (a) needs a thread primitive (spawn and join) and +; per-thread state; (d) needs packed-trit storage and an int8 SIMD dot product. (b) and (c) are +; spec work: t27 has f32, and a GEMM is loops over arrays. +pub fn lever_needs_backend(i: u32) -> bool { + if (i == LEVER_THREADS) { return true; } + if (i == LEVER_INT8) { return true; } + return false; +} + +pub fn lever_bound_e2(i: u32) -> u64 { + if (i == LEVER_THREADS) { return thread_bound_e2(LAB_CORES); } + if (i == LEVER_F32) { return amdahl_e2(matmul_ns(CLOCK_CPU), F32_X_E2); } + if (i == LEVER_GEMM) { return amdahl_e2(matmul_ns(CLOCK_CPU), GEMM_X_E2); } + return amdahl_e2(net_ns(CLOCK_CPU, CP_FWD_MM), INT8_X_E2); +} + +/// The lever with the highest bound; with backend false, only among levers t27c can build today. +pub fn biggest_lever(allow_backend: bool) -> u32 { + var i : u32 = 0; + var b : u32 = LEVERS; + while (i < LEVERS) { + if (allow_backend or !lever_needs_backend(i)) { + if (b == LEVERS) { + b = i; + } else { + if (lever_bound_e2(i) > lever_bound_e2(b)) { b = i; } + } + } + i = i + 1; + } + return b; +} + // ---------------------------------------------------------------- what is known and what is not -pub const NOT_MEASURED : [4]str = [ +pub const NOT_MEASURED : [11]str = [ "f, the share of a tern-tc-500m step spent in forward GEMMs", "cuBLAS itself; torch._int_mm is represented by the best CUTLASS s8 kernel", "activation quantization from bf16 to int8 and its kernel launch", - "the runner wired to torch._int_mm, end to end" + "the runner wired to torch._int_mm, end to end", + "the cost of the fixed-order gradient sum over N threads (lever a)", + "memory bandwidth with N trainer threads at once (lever a)", + "the speed of an f32 train_hslm (lever b)", + "whether each matmul kernel is weight-traffic bound, and the compute roof of a 27-position GEMM (lever c)", + "an int8 x packed-trit kernel, and the loss it gives (lever d)", + "the split on an unloaded host; the lab host ran at load 56 to 86", + "VSA and embedding time on its own: it is inside fwd_other" ]; // ---------------------------------------------------------------- tests @@ -269,6 +527,101 @@ test "what is not known stays written down" { assert NAME == "t27t"; } +test "the CPU profile adds up: parts to the printed total, marks to the call order" { + assert raw_sum(CLOCK_CPU) == CPU_TOTAL_NS; + assert raw_sum(CLOCK_WALL) == WALL_TOTAL_NS; + assert marks_sum() == CPU_TOTAL_MARKS; + // 66 windows x 27 positions a step, 19 kernel calls per position each way. + assert WINDOWS * SCORED_POSITIONS == 1782; + assert CPU_MARKS[CP_FWD_MM] == CPU_STEPS * 1782 * FWD_CALLS; + assert CPU_MARKS[CP_BWD_TADD] == CPU_MARKS[CP_FWD_MM]; + assert CPU_MARKS[CP_BWD_OUTER] == CPU_MARKS[CP_FWD_MM]; + assert CPU_MARKS[CP_ATT_FWD] == CPU_STEPS * 1782 * 3; + assert CPU_MARKS[CP_LOSS] == CPU_STEPS * 1782; + assert CPU_MARKS[CP_LAMB] == CPU_STEPS; + // profile 0 scored 1782 tokens a step. + assert (TOK_PER_S_P0_E1 * S_PER_STEP_P0_E4 + 50000) / 100000 == 1782; + assert CPU_PART_NAME[CP_BWD_OUTER] == "bwd_outer"; +} + +test "the wall clock closes on train_s, and the CPU-clock profile costs under 1%" { + assert (WALL_TOTAL_NS + 5000000) / 10000000 == WALL_TRAIN_S_E2; + assert S_PER_STEP_P2_E4 - S_PER_STEP_P0_E4 < S_PER_STEP_P0_E4 / 100; + // The clock reads: 0.907 s of the CPU-clock total, 0.087 s of the wall total. + assert CPU_TOTAL_NS - net_total(CLOCK_CPU) == 907241874; + assert WALL_TOTAL_NS - net_total(CLOCK_WALL) == 86973687; +} + +test "where a CPU step goes: 94.2% matmul, 66.8% backward matmul, 42.4% outer_add" { + assert net_total(CLOCK_CPU) == 124479038623; + assert share_e3(CLOCK_CPU, CP_FWD_MM) == 274; + assert share_e3(CLOCK_CPU, CP_BWD_TADD) == 245; + assert share_e3(CLOCK_CPU, CP_BWD_OUTER) == 424; + assert share_of(bwd_matmul_ns(CLOCK_CPU), net_total(CLOCK_CPU)) == 668; + assert share_of(matmul_ns(CLOCK_CPU), net_total(CLOCK_CPU)) == 942; + assert share_of(attention_ns(CLOCK_CPU), net_total(CLOCK_CPU)) == 17; + assert share_of(serial_ns(CLOCK_CPU), net_total(CLOCK_CPU)) == 6; + assert share_e3(CLOCK_CPU, CP_LAMB) == 3; + assert share_e3(CLOCK_CPU, CP_REQUANT) == 2; + assert biggest_part(CLOCK_CPU) == CP_BWD_OUTER; +} + +test "the wall clock gives the same matmul share and the same biggest part" { + assert share_of(matmul_ns(CLOCK_WALL), net_total(CLOCK_WALL)) == 941; + assert within_one(share_of(matmul_ns(CLOCK_WALL), net_total(CLOCK_WALL)), share_of(matmul_ns(CLOCK_CPU), net_total(CLOCK_CPU))); + assert share_e3(CLOCK_WALL, CP_BWD_OUTER) == 401; + assert biggest_part(CLOCK_WALL) == CP_BWD_OUTER; +} + +test "lever a: threads, bounded by ceil(66 / n) rounds and the serial tail" { + assert share_of(window_ns(CLOCK_CPU), net_total(CLOCK_CPU)) == 994; + assert thread_bound_e2(1) == 100; + assert thread_bound_e2(8) == 705; + assert thread_bound_e2(16) == 1226; + assert thread_bound_e2(48) == 2746; + assert thread_bound_e2(66) == 4683; + assert thread_limit_e2() == 15878; + assert lever_needs_backend(LEVER_THREADS); +} + +test "levers b, c, d: f32 1.89x, a 27-position GEMM 10.75x, forward int8 1.31x" { + assert lever_bound_e2(LEVER_F32) == 189; + assert lever_bound_e2(LEVER_GEMM) == 1075; + assert amdahl_e2(net_ns(CLOCK_CPU, CP_BWD_OUTER), GEMM_X_E2) == 169; + assert without_e2(matmul_ns(CLOCK_CPU)) == 1721; + assert lever_bound_e2(LEVER_INT8) == 131; + assert without_e2(net_ns(CLOCK_CPU, CP_FWD_MM)) == 138; + assert !lever_needs_backend(LEVER_F32); + assert !lever_needs_backend(LEVER_GEMM); + assert lever_needs_backend(LEVER_INT8); +} + +test "the biggest lever: threads with new backend support, the GEMM without" { + assert lever_bound_e2(LEVER_THREADS) == 2746; + assert biggest_lever(true) == LEVER_THREADS; + assert biggest_lever(false) == LEVER_GEMM; + assert LEVER_NAME[LEVER_GEMM] == "(c) one GEMM over 27 positions instead of a GEMV per position"; +} + +test "negative control: one CPU figure moved is caught" { + // One more second of forward matmul moves its share from 27.4% to 27.9%. + assert share_of(net_ns(CLOCK_CPU, CP_FWD_MM) + 1000000000, net_total(CLOCK_CPU) + 1000000000) == 279; + assert share_of(net_ns(CLOCK_CPU, CP_FWD_MM) + 1000000000, net_total(CLOCK_CPU) + 1000000000) != share_e3(CLOCK_CPU, CP_FWD_MM); + // The serial tail counted as parallel would lift the thread bound. + assert speedup_e2(net_total(CLOCK_CPU), net_total(CLOCK_CPU) / WINDOWS) > thread_bound_e2(66); + assert raw_sum(CLOCK_CPU) != CPU_TOTAL_NS + 1; +} + +test "what the CPU profile did not measure stays written down" { + assert NOT_MEASURED[4] == "the cost of the fixed-order gradient sum over N threads (lever a)"; + assert NOT_MEASURED[7] == "whether each matmul kernel is weight-traffic bound, and the compute roof of a 27-position GEMM (lever c)"; + assert NOT_MEASURED[10] == "VSA and embedding time on its own: it is inside fwd_other"; +} + +invariant threads_never_pass_the_serial_tail { thread_bound_e2(66) < thread_limit_e2() and thread_bound_e2(48) <= thread_bound_e2(66) } + +invariant the_cpu_parts_sum_to_the_printed_total { raw_sum(CLOCK_CPU) == CPU_TOTAL_NS and raw_sum(CLOCK_WALL) == WALL_TOTAL_NS } + invariant dp4a_is_never_picked { pick_path(PASS_FORWARD, false, 0) != PATH_DP4A and pick_path(PASS_FORWARD, true, 0) != PATH_DP4A } invariant gradients_stay_bf16 { pick_path(PASS_BACKWARD, true, 200) == PATH_BF16 } From 06968d7f316748bdc6df463dbd41011f2d6d0a2f Mon Sep 17 00:00:00 2001 From: Dmitrii Vasilev Date: Mon, 19 Oct 2026 12:38:07 +0700 Subject: [PATCH 4/4] seal(ml): re-seal train_hslm with the profile; ledger row blocker is now std.os.linux.timespec (#10850) Co-Authored-By: Claude Opus 5.5 --- .trinity/seals/ml_train_hslm.json | 18 +++++++++--------- docs/reports/t27b_expectations.json | 2 +- 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/.trinity/seals/ml_train_hslm.json b/.trinity/seals/ml_train_hslm.json index ae1d379241..0cd2ef83ca 100644 --- a/.trinity/seals/ml_train_hslm.json +++ b/.trinity/seals/ml_train_hslm.json @@ -1,5 +1,5 @@ { - "built_by": "t27c-bootstrap@0.5.2+78e57be99", + "built_by": "t27c-bootstrap@0.5.2+589e8e088", "closure": [ { "spec": "specs/base/types.t27", @@ -19,23 +19,23 @@ } ], "config": "gen=c,rust,verilog,zig;tests=zig", - "gen_hash_c": "sha256:9d92144a94228e46d3131ea7f5fe1bc86ead3a721add372e0051fee58317bc46", - "gen_hash_rust": "sha256:fa4751c35bca1feefaad3cd55dc1112fd7df2db4e6c5d7e21c34a024275d4285", - "gen_hash_verilog": "sha256:cf563313b4759cb371ab1a6f4aa5ad22e9770984d31d27bb2b7b448c48a54817", - "gen_hash_zig": "sha256:bbc14e0e851557974231ac8219526c2b75127e280d325f8c725f2131661c5874", + "gen_hash_c": "sha256:d1aab3569e7f81a5c9dde33f807f336fdf635a444123851f3af2337054e78adc", + "gen_hash_rust": "sha256:bc122390cb0e4fbb5874cb9a3b673821dac1ec2688218810ceeed920723680e0", + "gen_hash_verilog": "sha256:62ccb084432145a73480df7b3341a8e850ef4f3f09d48cbb063d392d9f6dd285", + "gen_hash_zig": "sha256:1173b9ccf2990e4d0bd8478d24c85f5fd40c7d5c0c410535a403f3dc0ccd9518", "module": "train_hslm", "ring": 12, "seal_schema": 2, - "sealed_at": "2026-10-19T05:13:11Z", + "sealed_at": "2026-10-19T05:47:55Z", "sealed_by": "t27c-bootstrap@0.5.2", - "spec_hash": "sha256:8218a7d2003b4b78582badf5e5b3bb42117455e722a4f4805b18963c2c092859", + "spec_hash": "sha256:b4c888de5e9f260644eb98b0374fa55820be75a5a01b7ec988097b1cc9c65ddc", "spec_path": "specs/ml/train_hslm.t27", "tests": { "failed": 0, "failing": [], "forced": false, - "passed": 27, - "total": 27, + "passed": 29, + "total": 29, "vacuous": 0 }, "toolchain": { diff --git a/docs/reports/t27b_expectations.json b/docs/reports/t27b_expectations.json index 7e3363a205..033fe648ce 100644 --- a/docs/reports/t27b_expectations.json +++ b/docs/reports/t27b_expectations.json @@ -589,7 +589,7 @@ {"path": "specs/ml/rl/ppo_critic.t27", "t27b": "blocked", "blocker": "ExprCall(undeclared fn)", "reason": "unimplemented"}, {"path": "specs/ml/rl/sac_actor.t27", "t27b": "blocked", "blocker": "ExprCall(undeclared fn)", "reason": "unimplemented"}, {"path": "specs/ml/rl/sac_critic.t27", "t27b": "pass"}, - {"path": "specs/ml/train_hslm.t27", "t27b": "blocked", "blocker": "ExprCall(undeclared fn)", "reason": "unimplemented"}, + {"path": "specs/ml/train_hslm.t27", "t27b": "blocked", "blocker": "type std.os.linux.timespec", "reason": "unimplemented"}, {"path": "specs/ml/train_slice_model.t27", "t27b": "blocked", "blocker": "ExprCall(undeclared fn)", "reason": "unimplemented"}, {"path": "specs/ml/transformer/encoder_block.t27", "t27b": "blocked", "blocker": "ExprCall(undeclared fn)", "reason": "unimplemented"}, {"path": "specs/ml/transformer/feed_forward_network.t27", "t27b": "pass"},