app: fizzy times its own startup, and a handover's

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);

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;

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()) {