From c947bd3a9e45b7317dd279d808616dd187ed4f43 Mon Sep 17 00:00:00 2001 From: foxnne Date: Sat, 10 Oct 2026 15:25:51 -0500 Subject: [PATCH 1/2] core: the profiler says why each frame happened fizzy draws only when something asks, so the frame-loop bugs are a frame that never comes and frames that never stop. While the profiler records, each frame is now put down to its events, else to the dvui.refresh calls before it by file and line, else to something else (a timer, an animation), and the report gains a .causes section: the counts, and the places that asked for frames, most first. Kept beside the profiler under its own key, so its abi stays 4. Co-Authored-By: Claude Opus 5.5 --- build/app.zig | 1 + core/profile.zig | 91 +++++++++++++++++++ core/profile/FrameCauses.zig | 167 +++++++++++++++++++++++++++++++++++ src/Entry.zig | 10 +++ src/editor/Editor.zig | 6 ++ 5 files changed, 275 insertions(+) create mode 100644 core/profile/FrameCauses.zig diff --git a/build/app.zig b/build/app.zig index db6510c1e..c34866f03 100644 --- a/build/app.zig +++ b/build/app.zig @@ -567,6 +567,7 @@ pub fn construct(b: *std.Build, target: std.Build.ResolvedTarget, optimize: std. // The profiler's lookback: 30 seconds of windows a reader can sum over, and the frames // that went over budget. .{ "fizzy-profile-lookback-tests", "core/profile/Lookback.zig" }, + .{ "fizzy-profile-causes-tests", "core/profile/FrameCauses.zig" }, // The login-shell PATH cache: it owns its string whatever allocator the first caller // passed, and threads that ask at once resolve once. The shell spawn itself is not run. .{ "fizzy-shell-env-tests", "core/shell_env.zig" }, diff --git a/core/profile.zig b/core/profile.zig index 078357bf4..1c0bd43a8 100644 --- a/core/profile.zig +++ b/core/profile.zig @@ -27,6 +27,9 @@ const perf = @import("gfx/perf.zig"); /// What the profiler keeps past its half-second window: 30 seconds of windows, and the frames /// over budget (`lookback`). pub const Lookback = @import("profile/Lookback.zig"); +/// Why each frame happened: its events, the `dvui.refresh` calls before it by place, or something +/// else (a timer, an animation), kept while the profiler records (`frameCauses`). +pub const FrameCauses = @import("profile/FrameCauses.zig"); /// Bumped whenever `Profiler`'s layout changes. Part of the key the host publishes it under /// (`publish_key`), so a plugin built against another layout finds none and records nothing: the @@ -351,10 +354,15 @@ var is_host = false; /// nobody profiles. Published beside the profiler under a key of its own, so the profiler's /// layout, and the plugins built against it, are untouched. var host_lookback: ?*Lookback = null; +/// The host's frame causes, made like `host_lookback`, and started over each time the profiler +/// starts recording, so they say what happened while someone looked. +var host_causes: ?*FrameCauses = null; +var was_active = false; const publish_id: dvui.Id = @enumFromInt(0x6669_7a7a_7970_7266); // "fizzyprf" const publish_key = std.fmt.comptimePrint("_profiler{d}", .{abi}); const lookback_key = std.fmt.comptimePrint("_profiler_lookback{d}", .{Lookback.abi}); +const causes_key = std.fmt.comptimePrint("_profiler_causes{d}", .{FrameCauses.abi}); /// The profiler to record into: the host's own in the host, the one it published in a plugin. /// Null when there is none, or it was built with another layout. @@ -378,6 +386,73 @@ pub fn lookback() ?*Lookback { return @ptrFromInt(addr); } +/// Why the frames since the profiler started recording happened, from any image. Null until it +/// has recorded a frame. +pub fn frameCauses() ?*FrameCauses { + if (is_host) return host_causes; + if (dvui.current_window == null) return null; + const addr = dvui.dataGet(null, publish_id, causes_key, usize) orelse return null; + return @ptrFromInt(addr); +} + +/// Whether frame causes are being recorded: the host's profiler is. The app turns dvui's refresh +/// records on while it is (`dvui.debug.logRefresh`) and hands each to `noteRefresh` (`interceptLog`). +pub fn recordingCauses() bool { + return host_causes != null and host_profiler.active; +} + +/// A `dvui.refresh` from `file`:`line`, from any thread: counted toward the next frame's cause +/// while the profiler records. +pub fn noteRefresh(file: []const u8, line: u32, from_thread: bool) void { + if (!recordingCauses()) return; + host_causes.?.noteRefresh(file, line, from_thread); +} + +/// For the app's `std.Options.logFn`, first thing: dvui's refresh records (`{s}:{d} refresh`, +/// logged at debug while `dvui.debug.logRefresh` is on) are counted as frame causes. True when the +/// call was one of dvui's refresh-debugging lines, which the app then drops unless it is also +/// logging refreshes itself. Matched by format at compile time, so every other log call costs +/// nothing here; a test holds dvui to the formats (`fizzy-integration-tests`). +pub fn interceptLog(comptime level: std.log.Level, comptime scope: @EnumLiteral(), comptime format: []const u8, args: anytype) bool { + if (comptime level != .debug or scope != .dvui) return false; + if (comptime std.mem.eql(u8, format, "{s}:{d} refresh {?x}")) { + noteRefresh(args[0], @intCast(args[1]), false); + return true; + } + if (comptime std.mem.eql(u8, format, "{s}:{d} refreshBackend {?x}")) { + noteRefresh(args[0], @intCast(args[1]), true); + return true; + } + // Logged with the refresh records, at every frame's start. + return comptime std.mem.eql(u8, format, "Window.begin frame_time_ns {d}"); +} + +/// A plugin dylib's log line (`Host.logLine`), from its own dvui: its refresh records reach the +/// host as text, `: refresh ` or `refreshBackend`, and are counted like the host's +/// (`interceptLog`). True when the line was one, which the host then drops. Read only while +/// recording; a plugin's release build compiles the records out, so only its Debug builds name +/// their places. +pub fn interceptPluginLine(level: std.log.Level, message: []const u8) bool { + if (level != .debug or !recordingCauses()) return false; + const at = std.mem.indexOf(u8, message, " refresh") orelse return false; + const loc = message[0..at]; + const colon = std.mem.lastIndexOfScalar(u8, loc, ':') orelse return false; + const line = std.fmt.parseInt(u32, loc[colon + 1 ..], 10) catch return false; + noteRefresh(loc[0..colon], line, std.mem.startsWith(u8, message[at..], " refreshBackend")); + return true; +} + +/// The events this frame has to handle, less the one dvui adds to every frame (the pointer's +/// `position`, so hover follows it): it causes nothing. +fn causingEvents() usize { + var n: usize = 0; + for (dvui.events()) |e| { + if (e.evt == .mouse and e.evt.mouse.action == .position) continue; + n += 1; + } + return n; +} + /// Host only: the profiler the window shows and controls. pub fn host() *Profiler { return &host_profiler; @@ -393,6 +468,14 @@ pub fn hostFrameBegin(prev_submit_ns: ?u64) void { dvui.dataSet(null, publish_id, publish_key, @as(usize, @intFromPtr(&host_profiler))); if (host_lookback == null and host_profiler.active) host_lookback = Lookback.create(std.heap.page_allocator, max_entries) catch null; if (host_lookback) |lb| dvui.dataSet(null, publish_id, lookback_key, @as(usize, @intFromPtr(lb))); + const active = host_profiler.active; + if (host_causes == null and active) host_causes = std.heap.page_allocator.create(FrameCauses) catch null; + if (host_causes) |c| { + if (active and !was_active) c.* = .{}; + if (active) c.frameBegin(causingEvents()); + dvui.dataSet(null, publish_id, causes_key, @as(usize, @intFromPtr(c))); + } + was_active = active; } /// Host only, at the end of every frame. @@ -453,6 +536,9 @@ pub const ReportOptions = struct { /// Also the newest this many frames that went over budget (`Lookback.budget_ns`), each with /// its costliest scopes. hitches: usize = 0, + /// Also why the frames happened (`FrameCauses`), with at most this many of the places that + /// asked for them; 0 leaves it out. + causes: usize = 8, }; /// Each entry's own time in a frame whose times (`ns`, indexed as `Profiler.slice`) are given: @@ -515,6 +601,11 @@ pub fn report(p: *const Profiler, w: *std.Io.Writer, opts: ReportOptions) std.Io if (opts.over_ms > 0) try writeOver(p, lb, w, opts); if (opts.hitches > 0) try writeHitches(p, lb, w, opts); } + if (opts.causes > 0) if (frameCauses()) |c| { + try w.writeAll(" .causes = "); + try c.write(w, " ", opts.causes); + try w.writeAll(",\n"); + }; try w.writeAll("}\n"); } diff --git a/core/profile/FrameCauses.zig b/core/profile/FrameCauses.zig new file mode 100644 index 000000000..4533702a0 --- /dev/null +++ b/core/profile/FrameCauses.zig @@ -0,0 +1,167 @@ +//! Why each frame happened, kept while the profiler records (`core.profile`): fizzy draws only +//! when something asks, so the two frame-loop bugs are a frame that never comes (work waiting for +//! the next unrelated event) and frames that never stop (something asking for another every frame). +//! A profile shows where a frame's time goes; this says who asked for it. +//! +//! A frame is put down to its events (input, a window event), else to the `dvui.refresh` calls +//! since the last one, by the file and line that asked (from dvui's own refresh records, which +//! the app's log function hands to `noteRefresh`), else to something else: a timer or an animation +//! coming due. Refreshes are counted by place; the places are kept, the frames as counts. +//! +//! Its own allocation, published beside the profiler under its own key (as `Lookback`), so the +//! profiler's layout, and its `abi`, are untouched. std-only. `noteRefresh` may be called from +//! any thread (a worker waking the app), under a spin lock held for a few instructions. +const FrameCauses = @This(); + +const std = @import("std"); + +pub const abi: u32 = 1; +/// The places that asked for frames, kept by count. One past it counts as `other_places`. +pub const places_kept = 32; +const file_len = 64; + +lock: std.atomic.Value(bool) = .init(false), +/// Frames recorded, and what each was put down to. +frames: u32 = 0, +by_events: u32 = 0, +by_refresh: u32 = 0, +by_other: u32 = 0, +/// Refreshes since the last frame began: they caused the next one. +pending: u32 = 0, +places: [places_kept]Place = undefined, +places_len: usize = 0, +/// Refreshes from places past `places_kept`. +other_places: u32 = 0, + +pub const Place = struct { + /// The asking file's path, its tail when longer than `file_len`: a dylib's strings go with it + /// when it unloads, so it is copied. + file_buf: [file_len]u8, + file_len: u8, + line: u32, + count: u32, + /// Asked from a thread other than the UI's (`dvui.refresh` with a window, through the backend). + from_thread: bool, + + pub fn file(self: *const Place) []const u8 { + return self.file_buf[0..self.file_len]; + } +}; + +fn acquire(self: *FrameCauses) void { + while (self.lock.cmpxchgWeak(false, true, .acquire, .monotonic) != null) std.atomic.spinLoopHint(); +} + +fn release(self: *FrameCauses) void { + self.lock.store(false, .release); +} + +/// Start over: counts from now. +pub fn reset(self: *FrameCauses) void { + self.acquire(); + defer self.release(); + self.frames = 0; + self.by_events = 0; + self.by_refresh = 0; + self.by_other = 0; + self.pending = 0; + self.places_len = 0; + self.other_places = 0; +} + +/// A `dvui.refresh` from `file`:`line`. Any thread. +pub fn noteRefresh(self: *FrameCauses, file: []const u8, line: u32, from_thread: bool) void { + self.acquire(); + defer self.release(); + self.pending +|= 1; + const tail = file[file.len - @min(file.len, file_len) ..]; + for (self.places[0..self.places_len]) |*p| { + if (p.line == line and p.from_thread == from_thread and std.mem.eql(u8, p.file(), tail)) { + p.count +|= 1; + return; + } + } + if (self.places_len == places_kept) { + self.other_places +|= 1; + return; + } + var p: Place = .{ .file_buf = undefined, .file_len = @intCast(tail.len), .line = line, .count = 1, .from_thread = from_thread }; + @memcpy(p.file_buf[0..tail.len], tail); + self.places[self.places_len] = p; + self.places_len += 1; +} + +/// A frame begins, with `events` events to handle. On the UI thread. +pub fn frameBegin(self: *FrameCauses, events: usize) void { + self.acquire(); + defer self.release(); + self.frames +|= 1; + if (events > 0) { + self.by_events +|= 1; + } else if (self.pending > 0) { + self.by_refresh +|= 1; + } else self.by_other +|= 1; + self.pending = 0; +} + +/// As ZON: what the frames since the last `reset` were put down to, and the places that asked +/// for frames, most first (at most `top`). +pub fn write(self: *FrameCauses, w: *std.Io.Writer, indent: []const u8, top: usize) std.Io.Writer.Error!void { + self.acquire(); + defer self.release(); + try w.print(".{{\n{s} .frames = {d}, .by_events = {d}, .by_refresh = {d}, .by_other = {d},\n", .{ indent, self.frames, self.by_events, self.by_refresh, self.by_other }); + var order: [places_kept]u8 = undefined; + for (0..self.places_len) |i| order[i] = @intCast(i); + const Ctx = struct { + places: []const Place, + fn more(ctx: @This(), a: u8, b: u8) bool { + return ctx.places[a].count > ctx.places[b].count; + } + }; + std.mem.sort(u8, order[0..self.places_len], Ctx{ .places = self.places[0..self.places_len] }, Ctx.more); + try w.print("{s} .refreshed_from = .{{\n", .{indent}); + for (order[0..@min(top, self.places_len)]) |i| { + const p = &self.places[i]; + try w.print("{s} .{{ .place = \"{s}:{d}\", .count = {d}{s} }},\n", .{ indent, p.file(), p.line, p.count, if (p.from_thread) ", .from_thread = true" else "" }); + } + try w.print("{s} }},\n", .{indent}); + if (self.other_places > 0) try w.print("{s} .from_other_places = {d},\n", .{ indent, self.other_places }); + try w.print("{s}}}", .{indent}); +} + +test "a frame is put down to its events, else the refreshes before it, else something else" { + var c: FrameCauses = .{}; + c.frameBegin(2); + c.noteRefresh("src/editor/Editor.zig", 120, false); + c.noteRefresh("src/editor/Editor.zig", 120, false); + c.noteRefresh("plugins/text/src/Doc.zig", 9, true); + c.frameBegin(0); + c.frameBegin(0); + try std.testing.expectEqual(@as(u32, 3), c.frames); + try std.testing.expectEqual(@as(u32, 1), c.by_events); + try std.testing.expectEqual(@as(u32, 1), c.by_refresh); + try std.testing.expectEqual(@as(u32, 1), c.by_other); + + var out: std.Io.Writer.Allocating = .init(std.testing.allocator); + defer out.deinit(); + try c.write(&out.writer, "", 8); + const text = out.written(); + // The busiest place first. + const editor = std.mem.indexOf(u8, text, "src/editor/Editor.zig:120\", .count = 2").?; + const doc = std.mem.indexOf(u8, text, "plugins/text/src/Doc.zig:9\", .count = 1, .from_thread = true").?; + try std.testing.expect(editor < doc); + + c.reset(); + try std.testing.expectEqual(@as(u32, 0), c.frames); + try std.testing.expectEqual(@as(usize, 0), c.places_len); +} + +test "a long path keeps its tail, and places past the kept ones are counted together" { + var c: FrameCauses = .{}; + const long = "/a/very/long/path/that/goes/on/and/on/and/on/past/sixty/four/bytes/src/Thing.zig"; + c.noteRefresh(long, 1, false); + try std.testing.expect(std.mem.endsWith(u8, c.places[0].file(), "src/Thing.zig")); + for (0..places_kept + 3) |i| c.noteRefresh("x.zig", @intCast(i + 2), false); + try std.testing.expectEqual(@as(usize, places_kept), c.places_len); + try std.testing.expectEqual(@as(u32, 4), c.other_places); +} diff --git a/src/Entry.zig b/src/Entry.zig index 0be79507d..e327bc59e 100644 --- a/src/Entry.zig +++ b/src/Entry.zig @@ -250,6 +250,10 @@ pub fn main(main_init: std.process.Init) !u8 { pub const panic = if (crash.supported) std.debug.FullPanic(crash.panic) else dvui.App.panic; pub const std_options: std.Options = .{ .logFn = logFn, + // dvui's refresh records are debug lines, which a release build would compile out; they are + // what the profiler puts frames down to (`core.profile.interceptLog`). dvui's other debug lines + // are dropped in `logFn` outside Debug, as they were before. + .log_scope_levels = &.{.{ .scope = .dvui, .level = .debug }}, // In every build mode, not only the safe ones: a release crash is the one worth a report. .enable_segfault_handler = crash.supported, }; @@ -267,6 +271,9 @@ const sdk_version = std.fmt.comptimePrint("{f} ({x})", .{ // web) and also into `fizzy.OutputLog`, so fizzy's "Output" bottom panel can show it — except // while `FIZZY_LOG_REFRESH` is on, see `refresh_log_active`. fn logFn(comptime level: std.log.Level, comptime scope: @EnumLiteral(), comptime format: []const u8, args: anytype) void { + // A refresh record, counted as a frame's cause; printed only for `FIZZY_LOG_REFRESH`. + if (fizzy.core.profile.interceptLog(level, scope, format, args) and !refresh_log_active) return; + if (comptime scope == .dvui and level == .debug and @import("builtin").mode != .Debug) return; if (!refresh_log_active) fizzy.OutputLog.append(level, scope, format, args); dvui.App.logFn(level, scope, format, args); } @@ -431,6 +438,9 @@ pub fn AppDeinit(_: *dvui.Window) void { pub fn AppFrame() !dvui.App.Result { fizzy.core.hitch.frameBegin(); defer fizzy.core.hitch.frameEnd(); + // dvui's refresh records, while someone reads them: the profiler, as frame causes, or a + // `FIZZY_LOG_REFRESH` run. + _ = dvui.debug.logRefresh(refresh_log_active or fizzy.core.profile.recordingCauses()); fizzy.core.profile.hostFrameBegin(lastSubmitNs()); defer fizzy.core.profile.hostFrameEnd(); singleton.drainPending(); diff --git a/src/editor/Editor.zig b/src/editor/Editor.zig index 1426aefef..7842d26ef 100644 --- a/src/editor/Editor.zig +++ b/src/editor/Editor.zig @@ -2326,6 +2326,8 @@ fn fizzyAskCommandArguments(ctx: *anyopaque, command_id: []const u8) bool { fn fizzyLogLine(ctx: *anyopaque, level: std.log.Level, scope: []const u8, message: []const u8) void { _ = ctx; + // A plugin's dvui refresh record, counted as a frame cause while the profiler records. + if (fizzy.core.profile.interceptPluginLine(level, message)) return; fizzy.OutputLog.appendLine(level, scope, message); } @@ -2619,6 +2621,10 @@ fn wakeEventLoop() void { fn fizzyRefresh(ctx: *anyopaque) void { _ = ctx; + // A plugin asking for a frame, which goes past `dvui.refresh` and so past its records: counted + // as a frame cause here. Which plugin asked, `Host.refresh` does not say (a source location + // through it would move the SDK's boundary). + fizzy.core.profile.noteRefresh("Host.refresh (a plugin)", 0, false); // Safe from any thread (see `SDLBackend.refresh`'s doc comment) — a single call reliably // wakes the blocked event loop and produces exactly one composited frame; see // `render_bridge.refresh`'s doc comment for how that was verified. From 1d2829eb4ec1624b24e0462057d0ba3a5fb6f993 Mon Sep 17 00:00:00 2001 From: Colton Franklin <49629865+foxnne@users.noreply.github.com> Date: Sat, 10 Oct 2026 17:19:53 -0500 Subject: [PATCH 2/2] app: fizzy times its own startup, and a handover's (#365) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Part of `plans/DASHBOARD_PLAN.md`, "What performance work lacked": startup and handover phases. Stacked on #364 (it shares the report code); retarget to `main` once that merges. ## What changes **fizzy times its own startup.** `core.profile.phase(io, name)` stamps a moment of the app's start. fizzy stamps: - **at launch:** `main`, `lock` (the single-instance lock), `window` (the backend up: GPU, fonts), `editor`, `plugins`, `shown`, and `first frame`; - **in an instance a restart's handover started (#356):** `lock deferred (handover)`, `handover ready` and `handover lock`. Each run's first frame logs one line: ``` info: startup: up 1288 ms after main (window shown at 1198 ms) ``` **The phases in the report:** `core.profile.report` includes them with `.startup = true`, and they're published like `Lookback` and `FrameCauses`: their own data key, no change to the profiler's layout or `abi`. The new instance of a handover, read that way: ```zig .startup = .{ .{ .phase = "main", .ms = 0.0 }, .{ .phase = "lock deferred (handover)", .ms = 0.4 }, .{ .phase = "window", .ms = 151.6 }, .{ .phase = "editor", .ms = 175.6 }, .{ .phase = "plugins", .ms = 208.4 }, .{ .phase = "handover ready", .ms = 211.7 }, .{ .phase = "shown", .ms = 219.5 }, .{ .phase = "handover lock", .ms = 232.1 }, .{ .phase = "first frame", .ms = 301.9 }, }, ``` It already shows something to act on: **the window is shown about 80 ms before its first frame is drawn.** That's true of every launch, and in a handover the new window covers the old one for those 80 ms before it has drawn anything. A follow-up can show it after the first frame. Measuring a restart used to take a window sampler and a pid poller running outside fizzy, on macOS only. ## SDK impact - [x] Core-only or additive: `core.profile.phase`, `phases`, `Phases`, `ReportOptions.startup`. No fingerprint move. ## Verified - [x] **macOS:** - **A cold launch:** the startup line above. - **A handover:** the table above, read from the new instance through the agent plugin. That used a local build of it against this tree; the agent's own tool for this waits for the SDK release, since it's pinned to 0.2.22. - **The first version of this crashed at `main`:** the clock went through `dvui.io`, which the backend hadn't set yet. So `phase` takes the `io`. - **Gates:** `zig build`, `zig build test` (533/534, 1 skipped), `test-integration` (375/375), `check-web`, `test-sdk-version`. - [ ] Windows, Linux: CI. ## Follow-ups - **Show a window after its first frame is drawn,** not before, starting with a handover's. - **The real process start** (macOS `proc_pidinfo`, Windows `GetProcessTimes`, Linux `/proc/self/stat`), so `main` isn't time zero and dyld and static initialisation are counted. - **The agent's `fizzy_build`** on fizzy's repo reports the new instance's phases, once the SDK is released and the agent repinned. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5.5 --- core/profile.zig | 53 +++++++++++++++++++++++++++++++++++++++++++ src/Entry.zig | 28 ++++++++++++++++++++++- src/editor/Editor.zig | 4 +++- 3 files changed, 83 insertions(+), 2 deletions(-) diff --git a/core/profile.zig b/core/profile.zig index 1c0bd43a8..e005e3d16 100644 --- a/core/profile.zig +++ b/core/profile.zig @@ -363,6 +363,33 @@ const publish_id: dvui.Id = @enumFromInt(0x6669_7a7a_7970_7266); // "fizzyprf" const publish_key = std.fmt.comptimePrint("_profiler{d}", .{abi}); const lookback_key = std.fmt.comptimePrint("_profiler_lookback{d}", .{Lookback.abi}); const causes_key = std.fmt.comptimePrint("_profiler_causes{d}", .{FrameCauses.abi}); +const phases_key = std.fmt.comptimePrint("_profiler_phases{d}", .{Phases.abi}); + +/// The moments the app's start took, stamped by the app as it reaches them (`phase`): process +/// entry, the window, the plugins, the window shown, the first frame; and, for an instance a +/// restart started beside the old one, the handover's. Measured by the app itself, on every +/// platform, rather than from outside. Published beside the profiler under its own key. +pub const Phases = struct { + pub const abi: u32 = 1; + pub const max = 16; + /// Each phase's name: a string that lives as long as the process (a literal). + names: [max][]const u8 = undefined, + at_ns: [max]i128 = undefined, + len: usize = 0, + + /// Milliseconds from the first phase to phase `i`. + pub fn ms(self: *const Phases, i: usize) f64 { + return @as(f64, @floatFromInt(self.at_ns[i] - self.at_ns[0])) / std.time.ns_per_ms; + } + + /// As ZON: each phase and when it came, in milliseconds from the first. + pub fn write(self: *const Phases, w: *std.Io.Writer, indent: []const u8) std.Io.Writer.Error!void { + try w.writeAll(".{\n"); + for (0..self.len) |i| try w.print("{s} .{{ .phase = \"{s}\", .ms = {d:.1} }},\n", .{ indent, self.names[i], self.ms(i) }); + try w.print("{s}}}", .{indent}); + } +}; +var host_phases: Phases = .{}; /// The profiler to record into: the host's own in the host, the one it published in a plugin. /// Null when there is none, or it was built with another layout. @@ -453,6 +480,24 @@ fn causingEvents() usize { return n; } +/// Host only: the app's start has reached `name` (a string literal). The first call is time zero. +/// Past `Phases.max`, not kept. `io` reads the clock: the process's own before the backend has +/// set `dvui.io` (at the top of `main`), which the clock otherwise goes through. +pub fn phase(io: std.Io, name: []const u8) void { + if (host_phases.len == Phases.max) return; + host_phases.names[host_phases.len] = name; + host_phases.at_ns[host_phases.len] = std.Io.Clock.boot.now(io).nanoseconds; + host_phases.len += 1; +} + +/// The app's start, from any image. +pub fn phases() ?*const Phases { + if (is_host) return &host_phases; + if (dvui.current_window == null) return null; + const addr = dvui.dataGet(null, publish_id, phases_key, usize) orelse return null; + return @ptrFromInt(addr); +} + /// Host only: the profiler the window shows and controls. pub fn host() *Profiler { return &host_profiler; @@ -468,6 +513,7 @@ pub fn hostFrameBegin(prev_submit_ns: ?u64) void { dvui.dataSet(null, publish_id, publish_key, @as(usize, @intFromPtr(&host_profiler))); if (host_lookback == null and host_profiler.active) host_lookback = Lookback.create(std.heap.page_allocator, max_entries) catch null; if (host_lookback) |lb| dvui.dataSet(null, publish_id, lookback_key, @as(usize, @intFromPtr(lb))); + dvui.dataSet(null, publish_id, phases_key, @as(usize, @intFromPtr(&host_phases))); const active = host_profiler.active; if (host_causes == null and active) host_causes = std.heap.page_allocator.create(FrameCauses) catch null; if (host_causes) |c| { @@ -539,6 +585,8 @@ pub const ReportOptions = struct { /// Also why the frames happened (`FrameCauses`), with at most this many of the places that /// asked for them; 0 leaves it out. causes: usize = 8, + /// Also the app's start (`Phases`): when it reached each phase. + startup: bool = false, }; /// Each entry's own time in a frame whose times (`ns`, indexed as `Profiler.slice`) are given: @@ -601,6 +649,11 @@ pub fn report(p: *const Profiler, w: *std.Io.Writer, opts: ReportOptions) std.Io if (opts.over_ms > 0) try writeOver(p, lb, w, opts); if (opts.hitches > 0) try writeHitches(p, lb, w, opts); } + if (opts.startup) if (phases()) |ph| { + try w.writeAll(" .startup = "); + try ph.write(w, " "); + try w.writeAll(",\n"); + }; if (opts.causes > 0) if (frameCauses()) |c| { try w.writeAll(" .causes = "); try c.write(w, " ", opts.causes); diff --git a/src/Entry.zig b/src/Entry.zig index e327bc59e..ba736cfbe 100644 --- a/src/Entry.zig +++ b/src/Entry.zig @@ -143,6 +143,8 @@ pub const dvui_app: dvui.App = .{ }; pub fn main(main_init: std.process.Init) !u8 { + // Time zero for the app's start (`core.profile.phase`). + fizzy.core.profile.phase(main_init.io, "main"); crash.init(.{ .app = AppInfo.current.name, .version = AppInfo.current.version, .sdk = sdk_version }); std.log.info("{s} version {s} ({s})", .{ AppInfo.current.display_name, AppInfo.current.version, @tagName(@import("builtin").mode) }); @@ -229,6 +231,7 @@ pub fn main(main_init: std.process.Init) !u8 { }.f, }); try singleton.earlyStartup(appAllocator(), main_init); + fizzy.core.profile.phase(main_init.io, if (restart.startedByHandover()) "lock deferred (handover)" else "lock"); // Both read relative to where fizzy was launched, before `AppInit` moves to its own directory. Editor.Demo.readEnvTape(appAllocator(), main_init.io); @@ -307,6 +310,7 @@ var refresh_log_active = false; // Runs before the first frame, after backend and dvui.Window.init() pub fn AppInit(win: *dvui.Window) !void { + fizzy.core.profile.phase(dvui.io, "window"); // Snapshot the platform from DVUI's keybind selection. On native this is a // no-op; on wasm it tells `fizzy.core.platform.isMacOS()` what browser we're in. fizzy.core.platform.cacheFromWindow(win); @@ -358,6 +362,7 @@ pub fn AppInit(win: *dvui.Window) !void { const editor_ptr = try allocator.create(Editor); fizzy.setInstances(app_ptr, editor_ptr); editor_ptr.* = Editor.init(app_ptr) catch unreachable; + fizzy.core.profile.phase(dvui.io, "editor"); // Workbench fizzy-owned state: wire before plugin `register`. workbench.runtime.setWorkbench(&fizzy.editor().workbench); @@ -366,6 +371,7 @@ pub fn AppInit(win: *dvui.Window) !void { // workbench-api service whose `ctx` is this pointer). This loads the built-in plugins, // including pixi as a generic dylib that owns its own state + atlas packer. fizzy.editor().postInit() catch unreachable; + fizzy.core.profile.phase(dvui.io, "plugins"); // Whether dvui went quiet at the end of each frame, for the `automation` service's `settled`. if (comptime @hasDecl(dvui.backend, "frame_ended_hook")) dvui.backend.frame_ended_hook = frameEnded; @@ -405,10 +411,29 @@ pub fn AppInit(win: *dvui.Window) !void { // Started by a restart's handover: up and hidden, the session read. The old instance goes // now, and this window shows over its own at the same place (`restart`); the lock follows // once the old one lets go of it (`Editor.tick`). - if (restart.startedByHandover()) restart.signalReady(dvui.io); + if (restart.startedByHandover()) { + restart.signalReady(dvui.io); + fizzy.core.profile.phase(dvui.io, "handover ready"); + } // Chrome and geometry are settled — reveal the window (created hidden). fizzy.backend.showWindow(win); + fizzy.core.profile.phase(dvui.io, "shown"); +} + +/// The first frame has ended: the app is up. Says how long that took, once. +var first_frame_done = false; +fn noteFirstFrame() void { + if (first_frame_done) return; + first_frame_done = true; + fizzy.core.profile.phase(dvui.io, "first frame"); + const ph = fizzy.core.profile.phases() orelse return; + std.log.info("startup: up {d:.0} ms after main (window shown at {d:.0} ms)", .{ ph.ms(ph.len - 1), shownMs(ph) }); +} + +fn shownMs(ph: *const fizzy.core.profile.Phases) f64 { + for (0..ph.len) |i| if (std.mem.eql(u8, ph.names[i], "shown")) return ph.ms(i); + return 0; } // Run as app is shutting down before dvui.Window.deinit() @@ -443,6 +468,7 @@ pub fn AppFrame() !dvui.App.Result { _ = dvui.debug.logRefresh(refresh_log_active or fizzy.core.profile.recordingCauses()); fizzy.core.profile.hostFrameBegin(lastSubmitNs()); defer fizzy.core.profile.hostFrameEnd(); + defer noteFirstFrame(); singleton.drainPending(); // Once, or — while a demo is seeking — again and again unseen until it lands (`frames`). const player = &fizzy.editor().demo.player; diff --git a/src/editor/Editor.zig b/src/editor/Editor.zig index 7842d26ef..55697d49e 100644 --- a/src/editor/Editor.zig +++ b/src/editor/Editor.zig @@ -5101,8 +5101,10 @@ fn syncExecutableWatcher(editor: *Editor) void { fn driveHandover(editor: *Editor) void { // The new instance's side: the lock, once the old instance has let go of it. if (restart.startedByHandover()) { - if (restart.pollReleased(dvui.io, editor.app.gpa)) + if (restart.pollReleased(dvui.io, editor.app.gpa)) { @import("app").single_instance.acquireLock(editor.app.gpa, &.{}) catch |err| dvui.log.warn("restart: could not take the single-instance lock: {t}", .{err}); + fizzy.core.profile.phase(dvui.io, "handover lock"); + } return; } if (restart.canHandOver()) {