core: the profiler says why each frame happened

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" },

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,42 @@ 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});
+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.
@@ -378,6 +413,91 @@ 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, `<file>:<line> refresh <id>` 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 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;
@@ -393,6 +513,15 @@ 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| {
+        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 +582,11 @@ 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,
+    /// 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:
@@ -515,6 +649,16 @@ 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);
+        try w.writeAll(",\n");
+    };
     try w.writeAll("}\n");
 }
 

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