From 26dff11a6efd9e6f9c391818778d718b435b8f04 Mon Sep 17 00:00:00 2001 From: ashhart <71890694+ashhart@users.noreply.github.com> Date: Tue, 27 Oct 2026 23:49:12 +0000 Subject: [PATCH] qwen27: TF_Q27_PROFILE logs each round's class GPU times, and profiled replies carry gpu_seconds (#1215) @grantoverton's #1215, finished on main as one commit. TF_Q27_PROFILE=N attaches the gpu_profile trace to a native Metal Qwen3.8-27B server and logs each kernel class's GPU time every N decode rounds (1 means every 64). The DFlash2 drafter is its own class: a draft frame's buffers are recorded when it finishes. While a frame is open the trace's spans keep the frame's encoder, so a span's own buffer cannot overtake the frame's pending ops and feed the drafter stale state (the fix in f8c63b68, squashed into 6e03930c's change). As our review asked: - gpu_seconds is set only with TF_Q27_PROFILE on. Without it every reply is byte-identical to before. - It is the GPU-busy time of the target's forward passes the reply ran in, prompt pass included, with the spans' and the Neural Engine share's own buffers. A shared round counts whole in each reply that shared it, and the drafter's passes are not in it; docs/api.md says the same. - TF_Q27_PROFILE: unset, empty or 0 is off, 1 is every 64 rounds, N is every N, and any other value leaves profiling off with a warning. - Rounds are decode passes: a served prompt pass runs with the trace paused, unsplit and uncounted. - A frame's hold gives back the trace it took (not the one its profiler names at release) and never saturates. - 21e0ad77 (varied tokens in measure() and a new cost-cache key) is left out, for its own PR and A/B. test-q27-profile-host checks the trace (rounds, records, holds, the pause and the value), the lane host's stats with an untimed and a timed fake backend (same tokens and counts, gpu_seconds only when timed), and the OpenAI handler's reply bytes, whole and streamed: the profiled reply less its gpu_seconds member equals the unprofiled reply byte for byte. Co-authored-by: grantoverton <65690763+grantoverton@users.noreply.github.com> --- CHANGELOG.md | 2 + README.md | 1 + docs/api.md | 6 + zig/build/cuda.zig | 1 + zig/build/q27_profile_host.zig | 14 ++ zig/src/core/engine_api.zig | 2 + zig/src/core/gpu_profile.zig | 143 +++++++++++++++++- zig/src/core/lane_host.zig | 2 +- zig/src/core/lane_host_gpu_seconds_test.zig | 85 +++++++++++ zig/src/core/lane_host_tests.zig | 1 + zig/src/core/lanes/fake.zig | 3 + zig/src/core/lanes/stream.zig | 6 + zig/src/families/qwen27/decode_round.zig | 9 ++ .../qwen27/dflash/runtime_backend.zig | 4 + .../families/qwen27/dflash/runtime_frame.zig | 9 ++ zig/src/native/qwen27_draft.zig | 2 + zig/src/native/qwen27_lanes.zig | 4 + zig/src/native/qwen27_served.zig | 17 +++ zig/src/native/qwen27_slots.zig | 11 ++ zig/src/server/chat.zig | 4 +- zig/src/server/cli.zig | 5 +- zig/src/server/reply_gpu_seconds_test.zig | 107 +++++++++++++ zig/src/server/root.zig | 1 + zig/tests/qwen27/dflash_run.zig | 3 + 24 files changed, 435 insertions(+), 7 deletions(-) create mode 100644 zig/build/q27_profile_host.zig create mode 100644 zig/src/core/lane_host_gpu_seconds_test.zig create mode 100644 zig/src/server/reply_gpu_seconds_test.zig diff --git a/CHANGELOG.md b/CHANGELOG.md index b189d75634..250db2da9b 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/README.md b/README.md index 3d616f7630..467380fd36 100644 --- a/README.md +++ b/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 diff --git a/docs/api.md b/docs/api.md index b401aa069f..419e3c8d54 100644 --- a/docs/api.md +++ b/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 diff --git a/zig/build/cuda.zig b/zig/build/cuda.zig index 51403a41a1..ca58ba7ac4 100644 --- a/zig/build/cuda.zig +++ b/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); diff --git a/zig/build/q27_profile_host.zig b/zig/build/q27_profile_host.zig new file mode 100644 index 0000000000..66cbd67533 --- /dev/null +++ b/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); +} diff --git a/zig/src/core/engine_api.zig b/zig/src/core/engine_api.zig index 93d830f364..337f22a460 100644 --- a/zig/src/core/engine_api.zig +++ b/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. diff --git a/zig/src/core/gpu_profile.zig b/zig/src/core/gpu_profile.zig index 531bb24fd3..af1e020e35 100644 --- a/zig/src/core/gpu_profile.zig +++ b/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)); +} diff --git a/zig/src/core/lane_host.zig b/zig/src/core/lane_host.zig index c90dea1ad7..552e68b21d 100644 --- a/zig/src/core/lane_host.zig +++ b/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 } }); diff --git a/zig/src/core/lane_host_gpu_seconds_test.zig b/zig/src/core/lane_host_gpu_seconds_test.zig new file mode 100644 index 0000000000..22ca52819f --- /dev/null +++ b/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); +} diff --git a/zig/src/core/lane_host_tests.zig b/zig/src/core/lane_host_tests.zig index 1779ac9b5d..804d14cc59 100644 --- a/zig/src/core/lane_host_tests.zig +++ b/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 { diff --git a/zig/src/core/lanes/fake.zig b/zig/src/core/lanes/fake.zig index f90daf25f9..418329b8cb 100644 --- a/zig/src/core/lanes/fake.zig +++ b/zig/src/core/lanes/fake.zig @@ -90,6 +90,7 @@ pub const Fake = struct { runs: usize = 0, // `pieces` calls that ran image_words: bool = false, // an image row feeds a word of its image's identity, as a tower's row would image_rows: usize = 0, // image rows fed (`image_words`): the rows a tower had to make + gpu_charge: ?f64 = null, // each verify and step charges its streams this many GPU seconds, as a timed backend does pub fn deinit(x: *Fake) void { var it = x.lanes.valueIterator(); @@ -417,6 +418,7 @@ pub const Fake = struct { const x = self(ptr); const l = x.lane(s); try l.history.append(x.gpa, x.value(feed)); + if (x.gpu_charge) |g| s.chargeGpu(g); return x.draw(l, s, position, true); } @@ -433,6 +435,7 @@ pub const Fake = struct { if (x.fail_round == x.rounds) return error.GpuFailed; x.last_rows = 0; x.last_sampled = false; + if (x.gpu_charge) |g| for (windows) |w| w.stream.chargeGpu(g); for (windows, out) |w, o| { x.last_rows += w.rows(); x.last_sampled = x.last_sampled or w.stream.sampling != null; diff --git a/zig/src/core/lanes/stream.zig b/zig/src/core/lanes/stream.zig index 700d607aa2..b4fd3db522 100644 --- a/zig/src/core/lanes/stream.zig +++ b/zig/src/core/lanes/stream.zig @@ -224,6 +224,7 @@ pub const Stream = struct { measured: [plan_lanes.sizes.len + 1]plan_lanes.Measured = @splat(.{}), // each pick's round times past its table price priced: ?struct { choice: usize, ms: f64 } = null, // the pick that shaped the held window, at its table price min_rows: u32 = 0, + gpu_seconds: ?f64 = null, // a timed backend's passes this stream ran in (TF_Q27_PROFILE); null: untimed paused: bool = false, depth: ?State = null, mode: ?Mode = null, @@ -322,6 +323,11 @@ pub const Stream = struct { return s.context.items[s.prompt_len..]; } + /// A timed pass this stream ran in, counted whole toward its reply's `gpu_seconds`. + pub fn chargeGpu(s: *Stream, seconds: f64) void { + s.gpu_seconds = (s.gpu_seconds orelse 0) + seconds; + } + /// A long cycle ending at the last committed token (the runs before it indexed), then that token's run indexed. fn longCycle(s: *Stream) ?u32 { const e = s.emitted(); diff --git a/zig/src/families/qwen27/decode_round.zig b/zig/src/families/qwen27/decode_round.zig index f074c0adc0..d2b3a9eb2b 100644 --- a/zig/src/families/qwen27/decode_round.zig +++ b/zig/src/families/qwen27/decode_round.zig @@ -47,6 +47,8 @@ pub const Runner = struct { capture_taps: bool = false, accepted_chain: bool = false, last_gpu_seconds: f64 = 0, + gpu_seconds: f64 = 0, // with a trace attached: every pass's GPU-busy seconds, its spans' and share's buffers too + trace: ?*@import("core").gpu_profile.Trace = null, // TF_Q27_PROFILE's: each pass run while it is enabled is a round current_round: ?*const Round = null, current_gdn: ?*const GdnPlan = null, current_attention: ?*const attn.Plan = null, @@ -182,6 +184,7 @@ pub const Runner = struct { } pub fn profile(r: *Runner, trace: ?*@import("core").gpu_profile.Trace) void { + r.trace = trace; r.model.kernels.profiler = trace; r.model.glue.profiler = trace; r.gdn.profiler = trace; @@ -243,6 +246,8 @@ pub const Runner = struct { if (r.capture_taps) r.taps.begin(); const pool = mtl.objc.Pool.push(); defer pool.pop(); + const spanned = if (r.trace) |t| t.spanned else 0; // a profiled pass's spans commit buffers of their own + const handed = if (r.model.ane) |share| share.gpu_seconds else 0; var stages = forward.Stages{ .model = r.model, .rows = @intCast(round.ids.len), .hooks = .{ .ptr = r, .gdn = gdnForward, .attention = attentionForward, .tap = if (r.capture_taps) tap else null }, .head = head, .images = placed.images }; r.last_gpu_seconds = @import("core").segments.runCommitting(r.model.device, &.{r.model.queue}, r.model.config.layers, .concurrent, &stages, commit_every) catch |err| { r.failed = true; @@ -252,6 +257,10 @@ pub const Runner = struct { r.failed = true; return err; }; + if (r.trace) |t| { + r.gpu_seconds += r.last_gpu_seconds + (t.spanned - spanned) + (if (r.model.ane) |share| share.gpu_seconds - handed else 0); + t.round(); + } if (r.capture_taps) try r.taps.complete(); if (accepted) { for (round.slots, round.windows) |slot, window| r.offsets[slot] = window.start + @as(u32, @intCast(window.parents.len)); diff --git a/zig/src/families/qwen27/dflash/runtime_backend.zig b/zig/src/families/qwen27/dflash/runtime_backend.zig index ef6e1c743f..1999e2062a 100644 --- a/zig/src/families/qwen27/dflash/runtime_backend.zig +++ b/zig/src/families/qwen27/dflash/runtime_backend.zig @@ -176,6 +176,10 @@ pub const Backend = struct { if (b.frame.ops == first_part_ops or b.frame.ops % part_ops == 0) try b.frame.part(); return b.frame.encoder; } + /// TF_Q27_PROFILE: the frame's passes join `trace`'s `drafter` class, and its spans keep an open frame's encoder. + pub fn profile(b: *Backend, trace: ?*core.gpu_profile.Trace) void { + b.frame.profiler = trace; + } pub fn copy(b: *Backend, e: mtl.ComputeEncoder, x: Ref, y: Ref, rows: u32, width: u32) !void { try b.target.glue.unstack(e, .{ .buffer = x.buf, .offset = x.off }, .{ .buffer = y.buf, .offset = y.off }, .{ .rows = rows, .width = width, .stride = width, .offset = 0 }); e.barrier(); diff --git a/zig/src/families/qwen27/dflash/runtime_frame.zig b/zig/src/families/qwen27/dflash/runtime_frame.zig index c7e0184c79..3d99e72a33 100644 --- a/zig/src/families/qwen27/dflash/runtime_frame.zig +++ b/zig/src/families/qwen27/dflash/runtime_frame.zig @@ -32,6 +32,8 @@ pub const Frame = struct { part_count: usize = 0, ops: u32 = 0, residency: ?mtl.ResidencySet.Follow = null, + profiler: ?*@import("core").gpu_profile.Trace = null, // TF_Q27_PROFILE: each pass's buffers time its `drafter` class + hold: @import("core").gpu_profile.Hold = .{}, // while open, the trace's spans keep this frame's encoder pub fn setResident(f: *Frame, hook: ?mtl.ResidencySet.Follow) void { for (f.pool.items) |buffer| { if (f.residency) |h| h.leave(h.ctx, buffer); @@ -59,6 +61,7 @@ pub const Frame = struct { f.completed = false; f.part_count = 0; f.ops = 0; + f.hold.take(f.profiler); // a span's own buffer would overtake this frame's pending ops return f.epoch; } /// Commits the work so far and opens the next buffer behind a fence, so the GPU starts early; between ops only. @@ -85,12 +88,18 @@ pub const Frame = struct { if (failed(cb)) return error.DraftGpuFailure; } if (failed(f.cb)) return error.DraftGpuFailure; + if (f.hold.trace) |t| { + var seconds = f.cb.gpuSeconds(); + for (f.parts[0..f.part_count]) |cb| seconds += cb.gpuSeconds(); + t.record(.drafter, seconds); + } } pub fn release(f: *Frame) void { if (f.active and !f.completed) { f.encoder.end(); for (f.parts[0..f.part_count]) |cb| cb.wait(); // committed parts still use the pool } + f.hold.release(); f.active = false; f.external = null; } diff --git a/zig/src/native/qwen27_draft.zig b/zig/src/native/qwen27_draft.zig index 2b62315e8c..7c0375d54f 100644 --- a/zig/src/native/qwen27_draft.zig +++ b/zig/src/native/qwen27_draft.zig @@ -34,6 +34,7 @@ pub const Draft = struct { return err; }; d.* = .{ .gpa = gpa, .runner = runner, .model = model, .owns_model = owns_model, .generation = generation, .previous_capture = previous_capture, .previous_taps = previous_taps }; + model.backend.profile(runner.trace); // the target's TF_Q27_PROFILE trace times the drafter's passes too return d; } pub fn reset(d: *Draft) !void { @@ -63,6 +64,7 @@ pub const Draft = struct { d.generation.deinit(); d.runner.capture_taps = d.previous_capture; d.runner.taps.ids = d.previous_taps; + d.model.backend.profile(null); // a borrowed drafter outlives the host and its trace if (d.owns_model) d.model.deinit(); d.gpa.destroy(d); } diff --git a/zig/src/native/qwen27_lanes.zig b/zig/src/native/qwen27_lanes.zig index 38a99f11e9..ed44a0c58e 100644 --- a/zig/src/native/qwen27_lanes.zig +++ b/zig/src/native/qwen27_lanes.zig @@ -451,10 +451,12 @@ pub const Metal = struct { slots.promoteDue(b); const slot = try b.slotFor(s); const token = try b.value(feed); + const before = b.runner.gpu_seconds; if (b.drafter(slot)) |d| try d.advance(token) else { try (q.session.Session{ .runner = b.runner, .slot = slot }).step(token); if (b.ringOf(slot)) |g| try b.ringChunk(g, 1); } + slots.charge(b, s, before); var next: [1]u32 = undefined; try b.draw(s, 0, 1, &.{position}, &next, &.{}); return b.push(next[0]); @@ -504,7 +506,9 @@ pub const Metal = struct { b.round = try Round.init(b.gpa, inputs[0..windows.len], @intCast(r.model.config.conv_kernel), r.slots, @intCast(r.model.config.vocab)); b.count = windows.len; errdefer b.dropRound(); + const before = r.gpu_seconds; if (plain) try r.advance(&b.round.?, .all) else try r.verifyHead(&b.round.?, .all); + for (windows) |w| slots.charge(b, w.stream, before); // a shared round counts whole in each reply b.advanced = plain; b.rows = total; // every greedy window's rows from one argmax over the round; a sampled window draws on the host diff --git a/zig/src/native/qwen27_served.zig b/zig/src/native/qwen27_served.zig index 26946db9be..64e6c778db 100644 --- a/zig/src/native/qwen27_served.zig +++ b/zig/src/native/qwen27_served.zig @@ -35,6 +35,7 @@ pub const Host = struct { model: *q.model.Model, owns_model: bool, runner: q.decode_round.Runner, + trace: ?tf.gpu_profile.Trace = null, // TF_Q27_PROFILE: rounds' class GPU times to the log, gpu_seconds in replies draft: ?*lb.Draft = null, back: *lb.Metal, cfg: lanes.Config, @@ -327,8 +328,13 @@ pub fn attach(gpa: Allocator, io: std.Io, model: *q.model.Model, drafter: ?*q.df h.resident = null; h.disk_stage = null; h.vision = o.images; // closed with the host; a failed attach leaves it to the caller + h.trace = null; h.runner = try q.decode_round.Runner.initReady(gpa, model, slots, capacity + lb.max_rows, 1); errdefer h.runner.deinit(); + if (profileEvery()) |every| { + h.trace = .{ .queue = model.queue, .report_every = every }; // enabled once measure() has priced the windows + h.runner.profile(&h.trace.?); + } if (drafter) |d| h.draft = try lb.Draft.attach(gpa, &h.runner, d, false) else if (o.drafter) |d| h.draft = lb.Draft.open(gpa, io, model, &h.runner, d, if (o.drafter_bits == 4) .prepared_q4_reference else .bf16_reference) catch |err| { why.* = try std.fmt.allocPrint(a, "the native Qwen3.8-27B drafter cannot load {s} ({s})", .{ d, @errorName(err) }); return error.DrafterLoad; @@ -372,11 +378,21 @@ pub fn attach(gpa: Allocator, io: std.Io, model: *q.model.Model, drafter: ?*q.df if (o.learn) |l| try disk.attach(h, io, a, l); errdefer if (h.cache) |*store| if (store.disk) |r| r.deinit(); h.host.keepalive_target = .{ .ctx = &h.warm, .tick = mtl.keepalive.Target.tick }; + if (h.trace) |*t| t.enabled = true; // serving rounds count from here: measure() timed whole, unsplit buffers try h.host.start(); std.log.info("Qwen3.8-27B: {d} streams of {d} tokens{s}{s}", .{ slots, capacity, if (h.draft != null) ", DFlash2 drafts for one of them" else "", if (o.images != null) ", images read" else "" }); return h; } +/// TF_Q27_PROFILE's rounds between log reports, or null (off); a value it cannot read leaves profiling off. +fn profileEvery() ?u64 { + const v = std.mem.span(platform.c.getenv("TF_Q27_PROFILE") orelse return null); + return tf.gpu_profile.every(v) catch { + std.log.warn("TF_Q27_PROFILE={s} is not 0, 1 or a round count: profiling stays off", .{v}); + return null; + }; +} + /// Reserve later buffers and the loaded share's priced bytes that its construction left outside the footprint. fn laterFootprint(h: *const Host) !u64 { const tower: u64 = if (h.back.vision) |v| v.firstUse() else 0; @@ -419,6 +435,7 @@ pub fn close(ptr: *anyopaque) void { h.cfg.deinit(h.gpa); h.back.deinit(); if (h.draft) |d| d.deinit(); + if (h.trace) |*t| t.reportRest(); h.runner.deinit(); if (h.vision) |v| v.deinit(); if (h.owns_model) h.model.deinit(); diff --git a/zig/src/native/qwen27_slots.zig b/zig/src/native/qwen27_slots.zig index 1889a6c755..c20d2ad4a8 100644 --- a/zig/src/native/qwen27_slots.zig +++ b/zig/src/native/qwen27_slots.zig @@ -59,8 +59,15 @@ pub fn closing(b: *Metal, s: *const lanes.Stream) void { if (b.image_fill == s) b.image_fill = null; } +/// With TF_Q27_PROFILE on, the target's passes since `before` count whole toward `s`'s reply (`gpu_seconds`). +pub fn charge(b: *const Metal, s: *lanes.Stream, before: f64) void { + if (b.runner.trace != null) s.chargeGpu(b.runner.gpu_seconds - before); +} + /// The pass's next chunk, its drafter's absorb before its marks; true once the prompt is in. pub fn chunk(b: *Metal, s: *lanes.Stream, f: *Fill) !bool { + const paused = tf.gpu_profile.pause(b.runner.trace); // prompt passes run unprofiled: TF_Q27_PROFILE's rounds decode + defer paused.end(); const ids = s.prompt(); const slot = f.slot; const d = b.drafter(slot); @@ -115,6 +122,7 @@ pub fn chunk(b: *Metal, s: *lanes.Stream, f: *Fill) !bool { }; const part = ids[at..end]; const last = end == ids.len; + const before = b.runner.gpu_seconds; if (d) |x| { if (decoded) try x.decodeChunk(part, last) else try x.promptChunk(part, last); } else { @@ -122,6 +130,7 @@ pub fn chunk(b: *Metal, s: *lanes.Stream, f: *Fill) !bool { if (decoded) try session.decodeChunk(part, last) else try session.promptChunk(part, last); if (b.ringOf(slot)) |g| try ringChunk(b, g, part.len); } + charge(b, s, before); f.at = end; s.fill_at.store(@intCast(end), .monotonic); // a prompt chunk waits: `at` is landed progress if (s.isCancelled()) return error.Cancelled; @@ -368,8 +377,10 @@ pub fn lone(b: *Metal, s: *lanes.Stream, hooks: api.LoneHooks) !bool { } const room: u32 = @intCast(s.max_new - s.emitted().len); copies.history = s.context.items; + const before = b.runner.gpu_seconds; const result = try g.runRound(room, b.nodes, s.eos, true, if (extra > 0) .{ .ptr = &copies, .call = Copies.call } else null, extra); defer b.gpa.free(result.tokens); + charge(b, s, before); if (result.extended > 0) { try copies.lookup.observe(result.extended, result.extension_landed); if (result.extension_landed == result.extended) extra = @min(cap, extra * 2) else if (2 * result.extension_landed < result.extended) extra = @max(@min(cap, 16), extra / 2); diff --git a/zig/src/server/chat.zig b/zig/src/server/chat.zig index c4851e6bbb..41ce3580e7 100644 --- a/zig/src/server/chat.zig +++ b/zig/src/server/chat.zig @@ -517,8 +517,8 @@ const Generation = struct { try runtime.put(a, "reasoning_effort", if (!thinking) .{ .string = "none" } else if (effort) |e| .{ .string = e } else .null); try runtime.put(a, "engine", .{ .string = g.srv.info.name }); try runtime.put(a, "tokens_per_second", .{ .float = if (decode_s > 0) @as(f64, @floatFromInt(decode_tokens)) / decode_s else 0 }); - // the reply's decode seconds, as tokens_per_second divides them - try runtime.put(a, "seconds", .{ .float = @max(0, decode_s) }); + try runtime.put(a, "seconds", .{ .float = @max(0, decode_s) }); // the reply's decode seconds, as tokens_per_second divides them + if (m.stats.gpu_seconds) |gpu| try runtime.put(a, "gpu_seconds", .{ .float = gpu }); // TF_Q27_PROFILE only try runtime.put(a, "prefill_seconds", if (m.stats.prefill_seconds) |p| .{ .float = p } else .null); const widths = try a.alloc(Value, m.widths.len); for (m.widths, widths) |w, *slot| slot.* = try json.intValue(a, w); diff --git a/zig/src/server/cli.zig b/zig/src/server/cli.zig index cf5d600b9c..47194fd13f 100644 --- a/zig/src/server/cli.zig +++ b/zig/src/server/cli.zig @@ -154,9 +154,10 @@ pub const flags = [_]Flag{ .{ .name = "--cortheon", .kind = .store_true, .native = true }, }; -/// The variables this binary honours as the Python engine does, then the CUDA build's. +/// The variables this binary honours as the Python engine does, then the CUDA build's or the Metal build's. pub const env = [_][]const u8{ "TENSORFOLD_API_KEY", "TENSORFOLD_NO_LIVE", "TENSORFOLD_SEED_SALT", "TENSORFOLD_REQUEST_LOG", "TENSORFOLD_NO_UPDATE_CHECK", "HF_HOME", "HF_HUB_CACHE", "HF_HUB_OFFLINE", "BRAVE_SEARCH_API_KEY" } ++ - (if (cuda_build) [_][]const u8{ "TF_CUDA_DEVICE", "TF_CUDA_SEGMENTS", "TENSORFOLD_CUDA_KERNELS", "TENSORFOLD_MEMORY_RESERVE_GIB", "TENSORFOLD_CUDA_MEMORY_LIMIT_GB", "TENSORFOLD_P2P_DIAGNOSTICS", "TENSORFOLD_P2P_PROBE" } else [_][]const u8{}); + (if (cuda_build) [_][]const u8{ "TF_CUDA_DEVICE", "TF_CUDA_SEGMENTS", "TENSORFOLD_CUDA_KERNELS", "TENSORFOLD_MEMORY_RESERVE_GIB", "TENSORFOLD_CUDA_MEMORY_LIMIT_GB", "TENSORFOLD_P2P_DIAGNOSTICS", "TENSORFOLD_P2P_PROBE" } else [_][]const u8{}) ++ + (if (builtin.os.tag == .macos) [_][]const u8{"TF_Q27_PROFILE"} else [_][]const u8{}); pub const Args = struct { admission: @import("request_admission.zig").Limits = .{}, diff --git a/zig/src/server/reply_gpu_seconds_test.zig b/zig/src/server/reply_gpu_seconds_test.zig new file mode 100644 index 0000000000..811cc405fb --- /dev/null +++ b/zig/src/server/reply_gpu_seconds_test.zig @@ -0,0 +1,107 @@ +//! A reply's `gpu_seconds` through the actual OpenAI handler: absent and byte-identical unless the engine timed it. +const std = @import("std"); +const api = @import("engine_api"); +const json = @import("json"); +const HfText = @import("hf_text.zig").HfText; +const fixture = @import("hf_eos_fixture.zig"); +const openai = @import("openai.zig"); +const Server = @import("server.zig").Server; +const Conn = @import("http_conn.zig").Conn; +const Allocator = std.mem.Allocator; + +/// An engine that answers three tokens and ends with `stats`, as a profiled or unprofiled host would. +const Script = struct { + stats: api.Stats, + fn engine(s: *Script) api.Engine { + return .{ .ctx = s, .vtable = &.{ .info = info, .submit = submit, .cancel = cancel, .status = status, .memory = memory } }; + } + fn info(_: *anyopaque) api.Info { + return .{ .context_window = 4096 }; + } + fn submit(ctx: *anyopaque, id: api.Id, _: *const api.Request, sink: api.Sink) api.SubmitError!void { + const s: *Script = @ptrCast(@alignCast(ctx)); + sink.event(sink.ctx, id, &.{ .prefilled = 0 }); + sink.event(sink.ctx, id, &.{ .tokens = &.{ 0, 1, 2 } }); + sink.event(sink.ctx, id, &.{ .finished = .{ .reason = .length, .stats = s.stats } }); + } + fn cancel(_: *anyopaque, _: api.Id) void {} + fn status(_: *anyopaque, out: *api.Status, _: []u32) void { + out.* = .{}; + } + fn memory(_: *anyopaque, _: bool) ?api.Memory { + return null; + } +}; + +/// The whole reply, or each streamed event, as the handler gave them. +const Reply = struct { + a: Allocator, + whole: ?json.Value = null, + events: std.ArrayList(json.Value) = .empty, + fn out(r: *Reply) openai.Out { + return .{ .ctx = r, .vt = &.{ .open = open, .event = event, .reply = reply } }; + } + fn open(_: *anyopaque, _: usize) error{Closed}!void {} + fn event(ctx: *anyopaque, value: ?json.Value) error{Closed}!void { + const r: *Reply = @ptrCast(@alignCast(ctx)); + if (value) |v| r.events.append(r.a, v) catch return error.Closed; + } + fn reply(ctx: *anyopaque, _: u16, value: json.Value) void { + const r: *Reply = @ptrCast(@alignCast(ctx)); + r.whole = value; + } +}; + +/// The reply's JSON bytes with its clock-dependent members fixed; `drop` names a runtime member to leave out. +fn steady(a: Allocator, value: json.Value, drop: ?[]const u8) ![]u8 { + const v = try json.deepCopy(a, value); + if (v.object.getPtr("id")) |p| p.* = .{ .string = "id" }; + if (v.object.getPtr("created")) |p| p.* = .{ .int = "0" }; + if (v.object.get("tensorfold")) |runtime| { + for ([_][]const u8{ "tokens_per_second", "seconds", "time_to_first_token" }) |k| { + if (runtime.object.getPtr(k)) |p| p.* = .null; + } + if (drop) |k| _ = runtime.object.orderedRemove(k); + } + return json.stringify(a, v, .{}); +} + +/// Every message the handler sent for a completion whose engine ended with `stats`, steadied, `drop` left out. +fn served(a: Allocator, stats: api.Stats, streaming: bool, drop: ?[]const u8) ![]const []u8 { + const gpa = std.testing.allocator; + var f = try fixture.Fixture.init(gpa, std.testing.io, null); + defer f.deinit(); + var problem: []const u8 = ""; + const text = try HfText.load(gpa, std.testing.io, f.path, null, a, &problem); + defer text.deinit(); + var script = Script{ .stats = stats }; + const srv = try Server.init(gpa, std.testing.io, script.engine(), text.text(), .{ .served_name = "m", .model_ids = &.{"m"}, .enable_thinking = false, .use_drafts = false }, null); + defer srv.deinit(); + const body = (try json.parse(a, if (streaming) "{\"model\":\"m\",\"prompt\":[0],\"max_tokens\":3,\"stream\":true}" else "{\"model\":\"m\",\"prompt\":[0],\"max_tokens\":3}")).ok; + var conn = Conn{ .fd = -1, .peer = "", .buf = &.{}, .gpa = a }; + var response = Reply{ .a = a }; + openai.run(srv, a, response.out(), .{ .conn = &conn }, false, body); + const values = if (streaming) response.events.items else &.{response.whole orelse return error.MissingReply}; + const out = try a.alloc([]u8, values.len); + for (values, out) |v, *bytes| bytes.* = try steady(a, v, drop); + return out; +} + +test "gpu_seconds: a reply whose engine did not time it is byte-identical, whole and streamed" { + var arena = std.heap.ArenaAllocator.init(std.testing.allocator); + defer arena.deinit(); + const a = arena.allocator(); + for ([_]bool{ false, true }) |streaming| { + const off = try served(a, .{ .rounds = 2, .drafted = 4, .accepted = 3, .min_rows = 2 }, streaming, null); + const on = try served(a, .{ .rounds = 2, .drafted = 4, .accepted = 3, .min_rows = 2, .gpu_seconds = 0.25 }, streaming, "gpu_seconds"); + const shown = try served(a, .{ .rounds = 2, .drafted = 4, .accepted = 3, .min_rows = 2, .gpu_seconds = 0.25 }, streaming, null); + try std.testing.expectEqual(off.len, on.len); + var timed: usize = 0; + for (off, on, shown) |x, y, z| { + try std.testing.expect(std.mem.indexOf(u8, x, "gpu_seconds") == null); + try std.testing.expectEqualStrings(x, y); // the profiled reply less its one member is the unprofiled reply + if (std.mem.indexOf(u8, z, "\"gpu_seconds\": 0.25") != null) timed += 1; + } + try std.testing.expectEqual(@as(usize, 1), timed); // the finish carries it, once + } +} diff --git a/zig/src/server/root.zig b/zig/src/server/root.zig index 07e2d0ed0f..4aa407a4c1 100644 --- a/zig/src/server/root.zig +++ b/zig/src/server/root.zig @@ -96,6 +96,7 @@ test { _ = @import("request_log.zig"); _ = @import("completion_prompt_test.zig"); _ = @import("hf_eos_http_test.zig"); + _ = @import("reply_gpu_seconds_test.zig"); _ = @import("server_init_test.zig"); _ = @import("connection_arena_test.zig"); _ = @import("decisions.zig"); diff --git a/zig/tests/qwen27/dflash_run.zig b/zig/tests/qwen27/dflash_run.zig index bb18eff6a0..c7b7bd60c2 100644 --- a/zig/tests/qwen27/dflash_run.zig +++ b/zig/tests/qwen27/dflash_run.zig @@ -72,6 +72,7 @@ pub fn main(init: std.process.Init) !void { const prompt_profiled = std.c.getenv("QWEN27_PROFILE_PROMPT") != null; if (prompt_profiled) { runner.profile(&trace); + draft.backend.profile(&trace); trace.enabled = true; } const start = std.Io.Clock.awake.now(io); @@ -82,10 +83,12 @@ pub fn main(init: std.process.Init) !void { for (trace.shapes[0..trace.shape_count]) |sh| std.debug.print("PROMPT shape n={d} k={d} sk={d} bits={d} calls={d} ms={d:.2}\n", .{ sh.n, sh.k, sh.sk, sh.bits, sh.calls, sh.gpu_seconds * 1e3 }); trace = .{ .queue = target.queue }; runner.profile(null); + draft.backend.profile(null); } const profiled = platform.c.getenv("QWEN27_PROFILE") != null; if (profiled) { runner.profile(&trace); + draft.backend.profile(&trace); trace.enabled = true; } const decode_start = std.Io.Clock.awake.now(io);