diff --git a/build.zig b/build.zig index 503ae788d..6ae87bf0a 100644 --- a/build.zig +++ b/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 diff --git a/skill-data/automation/SKILL.md b/skill-data/automation/SKILL.md index a7bc0de95..637d24149 100644 --- a/skill-data/automation/SKILL.md +++ b/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 ` 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 ` for the primary status item, or `native automate tray-action ` 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 (`_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 (`_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 diff --git a/src/automation/snapshot.zig b/src/automation/snapshot.zig index 2ac61b4a3..e4dd515de 100644 --- a/src/automation/snapshot.zig +++ b/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; diff --git a/src/platform/macos/appkit_host.m b/src/platform/macos/appkit_host.m index 3225c78dc..7079a2d1c 100644 --- a/src/platform/macos/appkit_host.m +++ b/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 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 { diff --git a/src/runtime/frame_profile.zig b/src/runtime/frame_profile.zig index 0f0d7442f..733fbb426 100644 --- a/src/runtime/frame_profile.zig +++ b/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); diff --git a/src/runtime/ui_app.zig b/src/runtime/ui_app.zig index 02589cbb0..92bbe5d63 100644 --- a/src/runtime/ui_app.zig +++ b/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) { diff --git a/tools/bench_render.zig b/tools/bench_render.zig index d613dc2ac..edfe348a1 100644 --- a/tools/bench_render.zig +++ b/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