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