From 5c7d6e45584a62ce25fa2ee933ddd85261c55e2a Mon Sep 17 00:00:00 2001 From: foxnne Date: Sat, 10 Oct 2026 15:49:18 -0500 Subject: [PATCH] app: fizzy times its own startup, and a handover's fizzy stamps the moments its start takes (core.profile.phase): main, the single-instance lock, the window, the editor, the plugins, the window shown, the first frame; and for an instance a restart started beside the old one, the handover's ready and lock. The first frame logs how long startup took, and the profiler's report has them on request (ReportOptions.startup). Measured by the app itself on every platform, where a restart's gap was measured from outside with a window sampler. 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 1c0bd43a..e005e3d1 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 e327bc59..ba736cfb 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 7842d26e..55697d49 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()) {