perf(macos): expose frame scheduler observability

build.zig

@@ -1170,6 +1170,11 @@ pub fn build(b: *std.Build) void {
         // one paced emission per display interval.
         .{ .path = "src/platform/macos/appkit_host.m", .pattern = "- (void)scheduleFrameEventEmission" },
         .{ .path = "src/platform/macos/appkit_host.m", .pattern = "- (void)emitScheduledFrameEvent" },
+        // Opt-in frame trace separates scheduler queue lateness from the
+        // synchronous engine dispatch and names whether its event was
+        // requested, completion-driven, or coalesced.
+        .{ .path = "src/platform/macos/appkit_host.m", .pattern = "deadline_ns=%llu block_start_ns=%llu queue_late_us=%llu producer=%s dispatch_us=%llu" },
+        .{ .path = "src/platform/macos/appkit_host.m", .pattern = "NativeSdkFrameEventProducerCoalesced" },
     });
     addFileContainsCheckStep(b, file_contains_checker, test_step, "test-quit-stop-queued", "Verify the quit verb's stop is queued to the next loop turn on every synchronous-emit host (a synchronous emitShutdown nests the shutdown dispatch inside the requesting command's dispatch, seals the session journal before the command commits, and replay diverges)", &.{
         // macOS (AppKit and CEF hosts): the main-queue hop, with the

skill-data/automation/SKILL.md

@@ -120,7 +120,7 @@ Semantics:
 13. Before driving an app-menu command, inspect the snapshot's `command id="..."` catalog and `app-menu` / `app-menu-item` rows to prove the running app loaded the expected `app.zon` or runner declarations. Then use `native automate menu-command <id>` to dispatch the same `.menu_command` platform event a real selection emits; the verb remains a raw event injector, so the snapshot receipt is what validates registration.
 14. Use `native automate tray-action <item-id>` for the primary status item, or `native automate tray-action <status-item-id> <item-id>` for an explicit item. Both select a dropdown row through the same platform event a real menu-bar click emits (command dispatch with source `.tray`). Live items appear in `snapshot.txt` as `tray #status-id title="..." visible=... items=N` followed by `  tray-item #item-id ...` rows — the menu bar is outside every window capture, so this is the automation evidence for every model-driven item. Unknown id pairs degrade into the dispatch-error ring as `automation.tray_action`.
 15. Use `native automate reload` to request a WebView reload.
-16. Use `native automate profile on` to enable per-stage frame timing: while on, `snapshot.txt` carries a `frame_profile` line with rolling p50/p90/max microseconds per pipeline stage (`rebuild`, `layout`, `reconcile`, `emit`, `a11y`, `plan`, `patch`, `encode`, `present`, `host_decode`, `host_draw`), each with a lifetime sample count (`<stage>_n=`). Drive some interactions, then `native automate snapshot | grep -o 'frame_profile.*'` to read where frame time goes; `profile off` stops recording and drops the line. Turning it on starts a fresh sample window.
+16. Use `native automate profile on` to enable per-stage frame timing: while on, `snapshot.txt` carries a `frame_profile` line with rolling p50/p90/max microseconds per pipeline stage (`effects`, `rebuild`, `layout`, `reconcile`, `emit`, `a11y`, `plan`, `patch`, `encode`, `present`, `host_decode`, `host_draw`, `interval`), each with a lifetime sample count (`<stage>_n=`). Drive some interactions, then `native automate snapshot | grep -o 'frame_profile.*'` to read where frame time goes; `profile off` stops recording and drops the line. Turning it on starts a fresh sample window.
 
 ## Screenshots
 

src/automation/snapshot.zig

@@ -1004,6 +1004,7 @@ test "snapshot emits the frame_profile line only while profiling" {
     var writer = std.Io.Writer.fixed(&buffer);
     const windows = [_]Window{.{ .title = "Test", .bounds = geometry.RectF.init(0, 0, 100, 100) }};
     const stages = [_]FrameProfileStage{
+        .{ .name = "effects", .p50_us = 75, .p90_us = 180, .max_us = 240, .count = 4 },
         .{ .name = "rebuild", .p50_us = 120, .p90_us = 340, .max_us = 900, .count = 12 },
         .{ .name = "encode", .p50_us = 8, .p90_us = 15, .max_us = 22, .count = 60 },
     };
@@ -1012,7 +1013,7 @@ test "snapshot emits the frame_profile line only while profiling" {
         .frame_profile = .{ .stages = &stages },
     }, &writer);
     const text = writer.buffered();
-    try std.testing.expect(std.mem.indexOf(u8, text, "\nframe_profile rebuild_p50_us=120 rebuild_p90_us=340 rebuild_max_us=900 rebuild_n=12 encode_p50_us=8 encode_p90_us=15 encode_max_us=22 encode_n=60\n") != null);
+    try std.testing.expect(std.mem.indexOf(u8, text, "\nframe_profile effects_p50_us=75 effects_p90_us=180 effects_max_us=240 effects_n=4 rebuild_p50_us=120 rebuild_p90_us=340 rebuild_max_us=900 rebuild_n=12 encode_p50_us=8 encode_p90_us=15 encode_max_us=22 encode_n=60\n") != null);
 
     // Profiling off -> no frame_profile line.
     var off_buffer: [512]u8 = undefined;

src/platform/macos/appkit_host.m

@@ -214,6 +214,21 @@ static uint64_t NativeSdkRetainedFrameIntervalNanoseconds(NSScreen *screen) {
  * heartbeat completion still marks the glass flush pending. */
 static const uint64_t NativeSdkOccludedFrameHeartbeatNs = 1000000000ull;
 
+typedef NS_ENUM(NSInteger, NativeSdkFrameEventProducer) {
+    NativeSdkFrameEventProducerRequest = 0,
+    NativeSdkFrameEventProducerCompletion = 1,
+    NativeSdkFrameEventProducerCoalesced = 2,
+};
+
+static const char *NativeSdkFrameEventProducerName(NativeSdkFrameEventProducer producer) {
+    switch (producer) {
+        case NativeSdkFrameEventProducerCompletion: return "completion";
+        case NativeSdkFrameEventProducerCoalesced: return "coalesced";
+        case NativeSdkFrameEventProducerRequest: return "request";
+    }
+    return "request";
+}
+
 static uint32_t NativeSdkModifierFlagsForEvent(NSEvent *event) {
     NSEventModifierFlags flags = event.modifierFlags & NSEventModifierFlagDeviceIndependentFlagsMask;
     uint32_t modifiers = 0;
@@ -561,6 +576,12 @@ @interface NativeSdkMetalSurfaceView : NSView <NSTextInputClient, NSDraggingDest
  * to a second out) is replaced by an immediate full-cadence one — the
  * dispatch source itself cannot be cancelled. */
 @property(nonatomic, assign) NSUInteger frameEventEmissionGeneration;
+/* Trace-only scheduler facts. They are populated only while
+ * NATIVE_SDK_GPU_FRAME_TRACE is enabled and copied to locals before the
+ * synchronous engine dispatch, which may schedule the following frame. */
+@property(nonatomic, assign) uint64_t frameEventTraceDeadlineNs;
+@property(nonatomic, assign) uint64_t frameEventTraceBlockStartNs;
+@property(nonatomic, assign) NativeSdkFrameEventProducer frameEventTraceProducer;
 /* One-shot: an input was dispatched to this surface and its responding
  * frame must not wait out the occluded heartbeat. Input is external
  * truth on its own cadence — automation drives covered windows
@@ -6104,7 +6125,10 @@ - (void)scheduleFrameEventEmission {
  * hostage for a second. */
 - (void)scheduleFrameEventEmissionForPresentCompletion:(BOOL)presentCompletion {
     if (![self isAvailable] || self.hidden || self.bounds.size.width <= 0 || self.bounds.size.height <= 0) return;
+    const BOOL tracing = NativeSdkGpuFrameTraceEnabled();
+    const BOOL coalesced = self.frameEventEmissionScheduled;
     if (self.frameEventEmissionScheduled) {
+        if (tracing) self.frameEventTraceProducer = NativeSdkFrameEventProducerCoalesced;
         if (!presentCompletion) return;
         self.frameEventEmissionGeneration += 1;
         self.frameEventEmissionScheduled = NO;
@@ -6134,6 +6158,12 @@ - (void)scheduleFrameEventEmissionForPresentCompletion:(BOOL)presentCompletion {
     if (self.retainedFrameLastEmitNs > 0 && now < self.retainedFrameLastEmitNs + paceNs) {
         delayNs = self.retainedFrameLastEmitNs + paceNs - now;
     }
+    if (tracing) {
+        self.frameEventTraceProducer = coalesced
+            ? NativeSdkFrameEventProducerCoalesced
+            : (presentCompletion ? NativeSdkFrameEventProducerCompletion : NativeSdkFrameEventProducerRequest);
+        self.frameEventTraceDeadlineNs = now + delayNs;
+    }
     const NSUInteger generation = self.frameEventEmissionGeneration;
     __weak NativeSdkMetalSurfaceView *weakSelf = self;
     dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)delayNs), dispatch_get_main_queue(), ^{
@@ -6143,6 +6173,7 @@ - (void)scheduleFrameEventEmissionForPresentCompletion:(BOOL)presentCompletion {
         // this block sat in the queue): the replacement owns the flag
         // and the activity — touch nothing.
         if (strongSelf.frameEventEmissionGeneration != generation) return;
+        if (tracing) strongSelf.frameEventTraceBlockStartNs = NativeSdkTimestampNanoseconds();
         strongSelf.frameEventEmissionScheduled = NO;
         [strongSelf emitScheduledFrameEvent];
         // The emission's engine dispatch re-arms the channel when more
@@ -6171,7 +6202,23 @@ - (void)emitScheduledFrameEvent {
     self.frameIndex += 1;
     const BOOL nonblank = self.verifiedNonblankFrame || self.hasCanvasTexture;
     const uint32_t sampleColor = self.verifiedNonblankFrame ? self.lastSampleColor : 0;
+    const BOOL tracing = NativeSdkGpuFrameTraceEnabled();
+    const uint64_t deadlineNs = tracing ? self.frameEventTraceDeadlineNs : 0;
+    const uint64_t blockStartNs = tracing ? self.frameEventTraceBlockStartNs : 0;
+    const NativeSdkFrameEventProducer producer = self.frameEventTraceProducer;
+    const uint64_t dispatchBeginNs = tracing ? NativeSdkTimestampNanoseconds() : 0;
     [self emitFrameEventWithFrameIndex:requestedFrameIndex sampleColor:sampleColor nonblank:nonblank occluded:[self occludedFramePacingActive]];
+    if (tracing) {
+        const uint64_t dispatchNs = NativeSdkTimestampNanoseconds() - dispatchBeginNs;
+        const uint64_t queueLateNs = blockStartNs > deadlineNs ? blockStartNs - deadlineNs : 0;
+        fprintf(stderr, "native-sdk: gpu scheduler-trace frame=%lu deadline_ns=%llu block_start_ns=%llu queue_late_us=%llu producer=%s dispatch_us=%llu\n",
+                (unsigned long)requestedFrameIndex,
+                (unsigned long long)deadlineNs,
+                (unsigned long long)blockStartNs,
+                (unsigned long long)(queueLateNs / 1000),
+                NativeSdkFrameEventProducerName(producer),
+                (unsigned long long)(dispatchNs / 1000));
+    }
 }
 
 - (void)renderFrame {

src/runtime/frame_profile.zig

@@ -26,6 +26,10 @@ pub const max_frame_profile_samples: usize = 128;
 
 /// The instrumented stage boundaries, in pipeline order.
 pub const FrameProfileStage = enum {
+    /// Effect completion dequeue plus every update/applyMsg in that
+    /// bounded completion batch. Rebuilds caused by the batch remain in
+    /// their existing rebuild/layout stages.
+    effects,
     /// App build fn + tree finalize (`UiApp.rebuild`'s view build).
     rebuild,
     /// Widget tree layout (`layoutWidgetTreeWithTokens`).
@@ -172,11 +176,16 @@ test "frame profile is inert while disabled" {
 
 test "frame profile records stage durations in microseconds" {
     var profile = FrameProfile{ .enabled = true };
+    profile.recordNs(.effects, 750_000);
     profile.recordNs(.layout, 1_500); // 1.5 us -> 1
     profile.recordNs(.layout, 2_000_000); // 2 ms -> 2000
     profile.recordNs(.encode, 42_000);
     try std.testing.expect(profile.hasSamples());
 
+    const effects_stats = profile.stats(.effects);
+    try std.testing.expectEqual(@as(u64, 750), effects_stats.p50_us);
+    try std.testing.expectEqual(@as(u64, 1), effects_stats.total);
+
     const layout_stats = profile.stats(.layout);
     try std.testing.expectEqual(@as(usize, 2), layout_stats.window_len);
     try std.testing.expectEqual(@as(u64, 2), layout_stats.total);

src/runtime/ui_app.zig

@@ -1821,11 +1821,13 @@ pub fn UiAppWithFeatures(comptime ModelT: type, comptime MsgT: type, comptime fe
             // ahead of this wake's event record answers a request from
             // an earlier dispatch, so replay's file-order feed always
             // finds the parked request (see Effects.DrainBoundary).
+            const effects_begin = runtime.frame_profile.begin();
             var boundary = self.effects.drainBoundary();
             while (self.effects.takeMsgWithin(&boundary)) |msg| {
                 self.applyMsg(msg);
                 dispatched = true;
             }
+            runtime.frame_profile.end(.effects, effects_begin);
             self.publishAudioState(runtime);
             var rebuild_error: ?anyerror = null;
             if (dispatched) {

tools/bench_render.zig

@@ -4,7 +4,7 @@
 //! frame planner, and the wire encoders all run exactly as they do under
 //! a live host. Measures end-to-end latency per interaction (input
 //! dispatch through present) and per-stage attribution via the runtime's
-//! frame profile (`rebuild`/`layout`/`reconcile`/`emit`/`plan`/`patch`/
+//! frame profile (`effects`/`rebuild`/`layout`/`reconcile`/`emit`/`plan`/`patch`/
 //! `encode`/`present`).
 //!
 //! What it deliberately does NOT measure: the macOS host's CoreText