qwen27: TF_Q27_PROFILE logs the round's class GPU times, and replies carry gpu_seconds

CHANGELOG.md

@@ -6,6 +6,8 @@ Each release's page on GitHub has its notes and measurements. See [the 1.0.0 rel
 
 - Kolibri-1 on CUDA, and Drama 3 with prompt chunks of more than one row (`TF_DRAMA_PREFILL_ROWS`): the block-FP8 routed experts' prompt kernels copy their weights into shared memory in stored order, so each 32-byte sector is read from L2 once instead of twice (#1460). The matrix multiplies read the same values in the same order, so outputs are the same bytes. On a GB10, Kolibri-1's prompts ran 13% faster at 2k tokens and 3 to 4% faster from 8k to 64k, with the same tokens. The kernel contract now records the register and shared-memory limits of Kolibri-1's three prompt launches. Thanks to @jschmied.
 
+- Qwen3.8-27B on Metal: `TF_Q27_PROFILE=N` logs each kernel class's GPU time, the DFlash2 drafter's included, every N decode rounds (`1` means every 64), and adds `gpu_seconds` to replies: the GPU time of the forward passes the reply ran in, with a round shared by several replies counted in each (#1215). It is a diagnostic and off by default: without it replies are byte-identical to before, and a value it cannot read leaves it off with a warning. Timing every round is slow: on an M5 Ultra one stream decodes at about a ninth of its usual rate with it on, so use it to diagnose, not to serve. Thanks to @grantoverton.
+
 ## 1.1.8
 
 - Qwen3.5 and 3.6 on HIP (Linux): when a checkpoint shard can't be memory-mapped and is read into memory instead (for example on some network or FUSE mounts), releasing an uploaded layer no longer zeroes that copy. Before, it also zeroed neighbouring tensors not yet uploaded: 269 of 690 layer tensors on Qwen3.5-2B, so the model ran on wrong weights or the loader panicked at close. A malformed shard header is now refused by name. Loads that map their shards are byte-identical to before.

README.md

@@ -342,6 +342,7 @@ one Mac; Qwen3.8-27B, Qwen3.5-2B, LFM2.5-24B-A2B, GLM-5.3 (EXLR8) and a CUDA ser
 Sampling defaults come from the checkpoint's `generation_config.json`, then serve flags and request fields override them.
 `--context 0` is family-specific; use a positive limit for GLM and inspect the capacity reported at startup.
 The supported environment variables are listed in `capabilities --json`, including API keys, request logging and Hugging Face cache paths.
+`TF_Q27_PROFILE=N` makes a native Metal Qwen3.8-27B server log a per-class GPU-time breakdown every N decode rounds (`1` means 64) and add `gpu_seconds` to its replies; it is diagnostic only, and a profiled round runs slower.
 
 ## Community benchmarks
 

docs/api.md

@@ -509,6 +509,12 @@ In the native block, `seconds` is the reply's decode time, from the end of its p
 `tokens_per_second` divides the reply's tokens after the first by it. `prefill_seconds` is the prompt pass, and
 `time_to_first_token` counts from the request's arrival, so a queued or long prompt shows there, not in `seconds`.
 The Python 0.6 server's `seconds` is the whole request, prompt included.
+A native Metal Qwen3.8-27B server started with `TF_Q27_PROFILE=N` logs each kernel class's GPU time, the DFlash2
+drafter's included, every N decode rounds (`1` means 64; unset, empty or `0` is off, and any other value leaves it off
+with a warning). Prompt passes run unprofiled, and a profiled round runs slower while its spans are timed. Its replies
+add `gpu_seconds` to the block: the GPU-busy time of the target model's forward passes the reply ran in, its prompt
+pass included. A round shared with other streams counts whole in each of their replies, and the drafter's passes
+are not included. Without `TF_Q27_PROFILE` the field is absent and replies are unchanged.
 
 The native server's finish log names the client reply ID. Completed requests report `prompt`, `cached`,
 `thinking`, `effort`, `tokens`, `sha`, `finish`, `rounds`, and draft acceptance; a refused request reports

zig/build/cuda.zig

@@ -375,6 +375,7 @@ pub fn hostTests(b: *std.Build, draft_ids: *std.Build.Module, build_options: *st
         .imports = &.{ .{ .name = "engine_api", .module = native_modules.api }, .{ .name = "tokenizer", .module = mods.tokenizer }, .{ .name = "template", .module = template }, .{ .name = "living", .module = mods.living } },
     });
     const server_json = @import("server.zig").addTo(b, server_tests, host, .debug);
+    @import("q27_profile_host.zig").steps(b, server_tests);
     b.step("test-drama-cfg-host", "Drama CFG CLI, HTTP and voice transitions without GPU execution").dependOn(&b.addRunArtifact(b.addTest(.{ .root_module = server_tests, .filters = &.{"CFG"} })).step);
     b.step("test-speech-redraw-deadline-host", "Busy speech redraw expiry without counting an unsubmitted take").dependOn(&b.addRunArtifact(b.addTest(.{ .root_module = server_tests, .filters = &.{"a busy redraw stops at its latest start"} })).step);
     @import("proposal_vocab_host.zig").steps(b, mods.core);

zig/build/q27_profile_host.zig

@@ -0,0 +1,14 @@
+//! TF_Q27_PROFILE's host checks: the trace's holds, pauses and value, and replies with and without gpu_seconds.
+const std = @import("std");
+
+pub fn steps(b: *std.Build, server_tests: *std.Build.Module) void {
+    const host = b.graph.host;
+    const fake = b.createModule(.{ .root_source_file = b.path("zig/src/qwen27_speed_metal.zig"), .target = host });
+    const profile = b.createModule(.{ .root_source_file = b.path("zig/src/core/gpu_profile.zig"), .target = host, .optimize = .debug, .imports = &.{.{ .name = "metal", .module = fake }} });
+    const lanes = b.createModule(.{ .root_source_file = b.path("zig/src/core/lanes/lanes.zig"), .target = host, .optimize = .debug, .link_libc = true });
+    const api = b.createModule(.{ .root_source_file = b.path("zig/src/core/engine_api.zig"), .target = host, .optimize = .debug, .link_libc = true, .imports = &.{.{ .name = "lanes", .module = lanes }} });
+    const step = b.step("test-q27-profile-host", "TF_Q27_PROFILE's trace, its value and replies' gpu_seconds, with no GPU");
+    step.dependOn(&b.addRunArtifact(b.addTest(.{ .root_module = profile })).step);
+    step.dependOn(&b.addRunArtifact(b.addTest(.{ .root_module = api, .filters = &.{"gpu_seconds:"} })).step);
+    step.dependOn(&b.addRunArtifact(b.addTest(.{ .root_module = server_tests, .filters = &.{"gpu_seconds:"} })).step);
+}

zig/src/core/engine_api.zig

@@ -160,6 +160,8 @@ pub const Stats = struct {
     loop_period: ?u32 = null,
     /// Prompt prefill duration measured by the engine host, in seconds.
     prefill_seconds: ?f64 = null,
+    /// The GPU-busy seconds of the forward passes the reply ran in, where profiling times them (TF_Q27_PROFILE).
+    gpu_seconds: ?f64 = null,
     /// Seconds from engine submission to first admission; an engine that admits immediately leaves zero.
     queued_seconds: f64 = 0,
     /// The drafter's own counters as a JSON object, or empty.

zig/src/core/gpu_profile.zig

@@ -1,8 +1,10 @@
 //! Diagnostic class timings split command buffers, wait for each span and keep ordinary encoders when disabled.
 const std = @import("std");
 const mtl = @import("metal");
-pub const Class = enum { dense, norm, xsum, embedding, copy, activation, gdn_prepare, gdn_scan, gdn_gate, state_publish, attention_prepare, attention };
+pub const Class = enum { dense, norm, xsum, embedding, copy, activation, gdn_prepare, gdn_scan, gdn_gate, state_publish, attention_prepare, attention, drafter };
 pub const Shape = struct { n: usize = 0, k: usize = 0, sk: usize = 0, bits: u8 = 0, calls: u64 = 0, gpu_seconds: f64 = 0 };
+/// The rounds between reports that TF_Q27_PROFILE=1 asks for.
+pub const default_every: u64 = 64;
 pub const Trace = struct {
     queue: mtl.Queue,
     enabled: bool = false,
@@ -11,12 +13,84 @@ pub const Trace = struct {
     shapes_overflow: bool = false,
     calls: [@typeInfo(Class).@"enum".field_names.len]u64 = @splat(0),
     seconds: [@typeInfo(Class).@"enum".field_names.len]f64 = @splat(0),
+    spanned: f64 = 0, // the spans' own command buffers' GPU seconds (a `record` is not a span)
+    rounds: u64 = 0, // forward passes run while enabled
+    report_every: u64 = default_every, // the class totals go to the log every this many rounds (0: only at close)
+    holds: u32 = 0, // open draft frames: a span keeps the frame's encoder, so the frame's pending ops stay in order
     pub fn begin(t: *Trace, e: mtl.ComputeEncoder, kind: Class) Scope {
-        if (!t.enabled) return .{ .encoder = e };
+        if (!t.enabled or t.holds != 0) return .{ .encoder = e };
         const cb = t.queue.commandBuffer();
         return .{ .encoder = cb.compute(.serial), .buffer = cb, .trace = t, .kind = kind };
     }
+    /// GPU seconds timed outside a Scope (a draft frame's own buffers) join `kind`'s totals.
+    pub fn record(t: *Trace, kind: Class, gpu_seconds: f64) void {
+        if (!t.enabled) return;
+        t.calls[@backingInt(kind)] += 1;
+        t.seconds[@backingInt(kind)] += gpu_seconds;
+    }
+    /// A forward pass completed; every `report_every` of them the class totals go to the log.
+    pub fn round(t: *Trace) void {
+        if (!t.enabled) return;
+        t.rounds += 1;
+        if (t.report_every > 0 and t.rounds % t.report_every == 0) t.report();
+    }
+    /// The class totals since the trace began, a log line each.
+    pub fn report(t: *const Trace) void {
+        if (t.rounds == 0) return;
+        var total: f64 = 0;
+        for (t.seconds) |seconds| total += seconds;
+        std.log.info("gpu profile: {d} rounds, {d:.1} ms", .{ t.rounds, total * 1e3 });
+        for (std.enums.values(Class), 0..) |kind, i| {
+            if (t.calls[i] == 0) continue;
+            std.log.info("gpu profile: {s:<18} {d:>6} calls {d:>9.2} ms {d:>8.3} ms/round", .{ @tagName(kind), t.calls[i], t.seconds[i] * 1e3, t.seconds[i] * 1e3 / @as(f64, @floatFromInt(t.rounds)) });
+        }
+    }
+    /// At close: the totals, unless the last round just logged them.
+    pub fn reportRest(t: *const Trace) void {
+        if (t.report_every == 0 or t.rounds % t.report_every != 0) t.report();
+    }
+};
+/// A draft frame's hold on its trace from begin to release: the trace it took is the one it gives back.
+pub const Hold = struct {
+    trace: ?*Trace = null,
+    pub fn take(h: *Hold, trace: ?*Trace) void {
+        std.debug.assert(h.trace == null);
+        const t = trace orelse return;
+        t.holds += 1;
+        h.trace = t;
+    }
+    pub fn release(h: *Hold) void {
+        const t = h.trace orelse return;
+        std.debug.assert(t.holds > 0);
+        t.holds -= 1;
+        h.trace = null;
+    }
 };
+/// A stretch outside the profile (a served prompt pass): spans stay unsplit and nothing counts until `end`.
+pub const Pause = struct {
+    trace: ?*Trace = null,
+    pub fn end(p: Pause) void {
+        if (p.trace) |t| t.enabled = true;
+    }
+};
+pub fn pause(trace: ?*Trace) Pause {
+    const t = trace orelse return .{};
+    if (!t.enabled) return .{};
+    t.enabled = false;
+    return .{ .trace = t };
+}
+/// TF_Q27_PROFILE's rounds between reports: unset, empty or 0 is off, 1 is every 64, N is every N; else invalid.
+pub fn every(value: ?[]const u8) error{InvalidProfile}!?u64 {
+    const v = value orelse return null;
+    if (v.len == 0) return null;
+    for (v) |c| if (!std.ascii.isDigit(c)) return error.InvalidProfile;
+    const n = std.fmt.parseInt(u64, v, 10) catch return error.InvalidProfile;
+    return switch (n) {
+        0 => null,
+        1 => default_every,
+        else => n,
+    };
+}
 pub const Scope = struct {
     encoder: mtl.ComputeEncoder,
     buffer: ?mtl.CommandBuffer = null,
@@ -41,6 +115,7 @@ pub const Scope = struct {
         const index = @backingInt(s.kind);
         t.calls[index] += 1;
         t.seconds[index] += cb.gpuSeconds();
+        t.spanned += cb.gpuSeconds();
         if (s.shape) |shape| {
             var found: ?usize = null;
             for (t.shapes[0..t.shape_count], 0..) |entry, j| if (entry.n == shape.n and entry.k == shape.k and entry.sk == shape.sk and entry.bits == shape.bits) {
@@ -71,3 +146,67 @@ test "disabled profiling keeps the caller encoder and records no spans" {
     try std.testing.expect(span.buffer == null);
     try std.testing.expectEqual(@as(u64, 0), trace.calls[0]);
 }
+
+test "gpu profile: rounds and records count only while enabled; a record is not a span" {
+    var trace = Trace{ .queue = undefined, .report_every = 0 }; // 0: the test writes no log lines
+    trace.round();
+    trace.record(.drafter, 0.5);
+    try std.testing.expectEqual(@as(u64, 0), trace.rounds);
+    try std.testing.expectEqual(@as(u64, 0), trace.calls[@backingInt(Class.drafter)]);
+    trace.enabled = true;
+    trace.record(.drafter, 0.5);
+    trace.round();
+    trace.round();
+    try std.testing.expectEqual(@as(u64, 2), trace.rounds);
+    try std.testing.expectEqual(@as(u64, 1), trace.calls[@backingInt(Class.drafter)]);
+    try std.testing.expectEqual(@as(f64, 0.5), trace.seconds[@backingInt(Class.drafter)]);
+    try std.testing.expectEqual(@as(f64, 0), trace.spanned);
+}
+
+test "gpu profile: a held trace keeps the frame's encoder, and each hold gives back the trace it took" {
+    var trace = Trace{ .queue = undefined, .enabled = true };
+    var first: Hold = .{};
+    var second: Hold = .{};
+    first.take(&trace);
+    second.take(&trace);
+    var span = trace.begin(undefined, .dense);
+    try span.end();
+    try std.testing.expect(span.buffer == null);
+    try std.testing.expectEqual(@as(u64, 0), trace.calls[@backingInt(Class.dense)]);
+    first.release();
+    try std.testing.expectEqual(@as(u32, 1), trace.holds);
+    second.release();
+    second.release(); // a hold gives its trace back once; no count wraps
+    try std.testing.expectEqual(@as(u32, 0), trace.holds);
+    first.take(null); // no profiler: no hold
+    first.release();
+    try std.testing.expect(first.trace == null);
+}
+
+test "gpu profile: a paused trace splits and counts nothing, then runs as before" {
+    var trace = Trace{ .queue = undefined, .enabled = true, .report_every = 0 };
+    const paused = pause(&trace);
+    var span = trace.begin(undefined, .attention);
+    try span.end();
+    trace.round();
+    trace.record(.drafter, 1);
+    try std.testing.expect(span.buffer == null);
+    paused.end();
+    try std.testing.expect(trace.enabled);
+    try std.testing.expectEqual(@as(u64, 0), trace.rounds);
+    try std.testing.expectEqual(@as(u64, 0), trace.calls[@backingInt(Class.drafter)]);
+    var off = Trace{ .queue = undefined };
+    pause(&off).end(); // a disabled trace stays disabled
+    try std.testing.expect(!off.enabled);
+    pause(null).end();
+}
+
+test "gpu profile: TF_Q27_PROFILE is off unless 1 (every 64 rounds) or a round count" {
+    try std.testing.expectEqual(@as(?u64, null), try every(null));
+    try std.testing.expectEqual(@as(?u64, null), try every(""));
+    try std.testing.expectEqual(@as(?u64, null), try every("0"));
+    try std.testing.expectEqual(@as(?u64, null), try every("000"));
+    try std.testing.expectEqual(@as(?u64, default_every), try every("1"));
+    try std.testing.expectEqual(@as(?u64, 16), try every("16"));
+    for ([_][]const u8{ "on", "true", "-1", "+2", " 1", "1 ", "1_0", "0x10", "1.5", "99999999999999999999" }) |v| try std.testing.expectError(error.InvalidProfile, every(v));
+}

zig/src/core/lane_host.zig

@@ -263,7 +263,7 @@ pub const LaneHost = struct {
         h.gpa.free(job.marks);
         h.gpa.free(job.key);
         const s = &job.stream;
-        const stats: Stats = if (job.started) .{ .rounds = s.rounds, .drafted = s.drafted, .accepted = s.accepted, .min_rows = s.min_rows, .loop_period = s.loop_period, .prefill_seconds = if (job.prefilled) |done| @as(f64, @floatFromInt(@as(i64, @intCast(@max(0, done - job.began))))) / 1e9 else null } else .{};
+        const stats: Stats = if (job.started) .{ .rounds = s.rounds, .drafted = s.drafted, .accepted = s.accepted, .min_rows = s.min_rows, .loop_period = s.loop_period, .gpu_seconds = s.gpu_seconds, .prefill_seconds = if (job.prefilled) |done| @as(f64, @floatFromInt(@as(i64, @intCast(@max(0, done - job.began))))) / 1e9 else null } else .{};
         var told = if (job.started) recalls.finished(h, job, reason, stats) else stats;
         told.queued_seconds = if (job.admitted_ns) |at| @as(f64, @floatFromInt(@max(0, at - job.submitted))) / 1e9 else 0;
         emit(job, .{ .finished = .{ .reason = reason, .stats = told, .message = message } });

zig/src/core/lane_host_gpu_seconds_test.zig

@@ -0,0 +1,85 @@
+//! A reply's gpu_seconds through the actual lane host: absent unless the backend times its passes (TF_Q27_PROFILE).
+const std = @import("std");
+const lanes = @import("lanes");
+const api = @import("engine_api.zig");
+const LaneHost = @import("lane_host.zig").LaneHost;
+const t = std.testing;
+
+/// A request's tokens, and its finished event's reason and counts.
+const Box = struct {
+    mutex: std.Io.Mutex = .init,
+    tokens: std.ArrayList(u32) = .empty,
+    failed: bool = false,
+    reason: ?api.Reason = null,
+    stats: api.Stats = .{},
+    fn event(ctx: *anyopaque, _: api.Id, e: *const api.Event) void {
+        const b: *@This() = @ptrCast(@alignCast(ctx));
+        b.mutex.lockUncancelable(t.io);
+        defer b.mutex.unlock(t.io);
+        switch (e.*) {
+            .tokens => |got| b.tokens.appendSlice(t.allocator, got) catch {
+                b.failed = true;
+            },
+            .finished => |f| {
+                b.stats = f.stats;
+                b.stats.prefill_widths = &.{}; // the event's slices are the host's: the counts are what stay
+                b.stats.prefill_raised = &.{};
+                b.stats.telemetry_json = "";
+                b.reason = f.reason;
+            },
+            else => {},
+        }
+    }
+    fn wait(b: *@This()) !void {
+        for (0..10_000) |_| { // 10 s
+            b.mutex.lockUncancelable(t.io);
+            const done = b.reason != null;
+            const failed = b.failed;
+            b.mutex.unlock(t.io);
+            if (failed) return error.OutOfMemory;
+            if (done) return;
+            std.Io.sleep(t.io, .fromMilliseconds(1), .awake) catch {};
+        }
+        return error.Timeout;
+    }
+};
+
+const prompt = [_]u32{ 3, 1, 4, 1, 5 };
+const request: api.Request = .{ .prompt = &prompt, .max_tokens = 24 };
+
+/// One request through a lane host over the fake target, which charges `charge` GPU seconds a pass (null: untimed).
+fn reply(charge: ?f64, box: *Box) !void {
+    const gpa = t.allocator;
+    var cfg = try lanes.Config.init(gpa, .{ .exact_width = 8, .gpu_tokens = true, .hidden_rows = true }, 8, 7);
+    defer cfg.deinit(gpa);
+    var target: lanes.fake.Fake = .{ .gpa = gpa, .gpu_charge = charge };
+    defer target.deinit();
+    var clock: lanes.fake.FixedClock = .{};
+    var core = lanes.Engine.init(gpa, &cfg, target.backend(), clock.clock());
+    defer core.deinit();
+    var host = LaneHost.init(gpa, t.io, &core, .{ .lanes = 2 });
+    try host.start();
+    defer host.stop();
+    try host.engine().submit(1, &request, .{ .ctx = box, .event = Box.event });
+    try box.wait();
+}
+
+test "gpu_seconds: an untimed backend's reply carries none, and timing changes no token or count" {
+    var off: Box = .{};
+    defer off.tokens.deinit(t.allocator);
+    try reply(null, &off);
+    var on: Box = .{};
+    defer on.tokens.deinit(t.allocator);
+    try reply(0.25, &on);
+    try t.expect(off.stats.gpu_seconds == null);
+    try t.expect(on.stats.rounds > 0);
+    try t.expect(on.stats.gpu_seconds.? >= 0.25 * @as(f64, @floatFromInt(on.stats.rounds))); // every round it ran in
+    try t.expectEqual(api.Reason.length, off.reason.?);
+    try t.expectEqual(off.reason, on.reason);
+    try t.expectEqualSlices(u32, off.tokens.items, on.tokens.items);
+    try t.expectEqual(off.stats.rounds, on.stats.rounds);
+    try t.expectEqual(off.stats.drafted, on.stats.drafted);
+    try t.expectEqual(off.stats.accepted, on.stats.accepted);
+    try t.expectEqual(off.stats.min_rows, on.stats.min_rows);
+    try t.expectEqual(off.stats.loop_period, on.stats.loop_period);
+}

zig/src/core/lane_host_tests.zig

@@ -19,6 +19,7 @@ test {
 
 test {
     _ = @import("lane_host_interior_test.zig");
+    _ = @import("lane_host_gpu_seconds_test.zig");
 }
 
 test {