[Feature] Engine lock types with diagnostics as a build mode, and the four busiest locks moved

Examples/PerfBench/README.md

@@ -22,6 +22,12 @@ compared with a number from after it.
 | `animation-16` | 16 skinned characters running: the animation system and GPU skinning. |
 | `stadium` | The stadium and grass assets: material binds and textures. |
 | `gaussian` | A small Gaussian splat plus primitives: the splat cull, depth-key and radix-sort passes. |
+| `locks-api` | The 1k grid with game code reading and moving every entity through the public API each frame: what the API costs in lock calls. |
+| `locks-loading` | The 1k grid while an asset loads, is destroyed and loads again: contention between the loader's threads and the frame. |
+| `locks-threads` | The 1k grid while a second thread reads every entity's transform in a loop, as a render thread reads what the main thread updates on visionOS: contention and wait on the scene's locks. |
+
+The three `locks-` scenes are judged on lock numbers in the `locks` session below, and on frame
+and CPU times like any other scene in a normal build.
 
 Assets come from `Tests/UntoldEngineRenderTests/Resources`; the project copies the `Models` and
 `Animations` folders and the splat file into the app bundle.
@@ -50,15 +56,28 @@ the window server does not rescale it on the GPU that is being measured.
 ```bash
 brew install xcodegen                      # once
 
-scripts/perf/run_bench.sh macos                                  # this Mac
+scripts/perf/run_bench.sh macos --session quick                  # the gate for every change, about 3 min
+scripts/perf/run_bench.sh macos --session locks                  # lock calls and lock wait time per frame
+scripts/perf/run_bench.sh macos --session full                   # every scene, then the locks session
+
+scripts/perf/run_bench.sh macos                                  # this Mac, every scene once
 scripts/perf/run_bench.sh visionos --device "Javier's Apple Vision Pro"
 scripts/perf/run_bench.sh ios --device <udid>
 
 scripts/perf/run_bench.sh macos --scenes primitives-1k,postfx --seconds 10
 scripts/perf/run_bench.sh macos --update-baseline                # store this run as the baseline
 scripts/perf/run_bench.sh visionos --device <udid> --xctrace "Metal System Trace"
+scripts/perf/run_bench.sh macos --lock-diagnostics               # count and time every engine lock
 ```
 
+The three sessions:
+
+| Session | What it runs | Judged on |
+|---|---|---|
+| `quick` | `cube`, `primitives-1k`, `animation-16`, `stadium`; 10 s each, three repeats | The baseline: frame pacing, per-system CPU time, GPU time where the GPU is busy. Run it for every change. |
+| `locks` | `primitives-1k` and the three `locks-` scenes in a build with `ENGINE_LOCK_DIAGNOSTICS`; two repeats | The lock baseline (`perf/baselines/<model>/<platform>-lockdiag/`): lock calls per frame and lock wait time per frame, per lock name. Lock calls repeat to within 0.1 % between runs. |
+| `full` | Every scene with three repeats, then the `locks` session | Both. With `--update-baseline` it refreshes both baselines. |
+
 Runs land in `perf/results/<timestamp>-<platform>/` with `<scene>.jsonl`, `summary.json` and the
 console log. The comparison prints one block per scene and exits non-zero on a regression (10 %
 on frame-time, GPU-time and per-system CPU metrics, 0.5 points on the over-budget and
@@ -78,7 +97,16 @@ not: with the GPU idle most of the frame they follow its clock state, and one fr
 time measured 0.8 and 2.2 ms in consecutive runs of the same build. The comparer therefore judges
 GPU times only when the baseline shows the GPU busy for at least half the frame, and prints them
 as information otherwise; judge GPU cost on the headset, where the GPU is busy and run-to-run
-noise is under 10 %.
+noise is under 10 %. Small CPU times behave the same way (the cube scene's encode time measured
+0.2 and 0.8 ms in consecutive runs of the same build), so a per-system CPU mean is judged only
+when the baseline's value is at least 1 ms.
+
+A Mac is rarely idle. Each scene records how many CPU cores other processes used while it was
+recorded, and the console line says `MACHINE BUSY` from one core up. When even the quietest of the
+repeats was that busy, the comparer reports the scene's frame pacing as information instead of
+judging it, and says so at the end: skipped refreshes are then the machine's, not the engine's.
+Photo and media analysis daemons are the usual cause; they start on their own when the Mac sits on
+mains power. The CPU means of the heavier systems hold up under that load and are still judged.
 
 The app can also be opened in Xcode (`xcodegen generate`, then `PerfBench.xcodeproj`) and started
 from its Start button; it reads its configuration from the environment:

Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift

@@ -68,6 +68,9 @@ public struct BenchRenderSettings: Codable, Sendable {
     public var displayRefreshHz: Double = 0.0
     /// Anti-aliasing mode the scenes ran with (the post-FX scene always uses SMAA).
     public var antiAliasing: String = "fxaa"
+    /// Whether the engine was compiled with `ENGINE_LOCK_DIAGNOSTICS`. Such a build counts and
+    /// times every engine lock, so its frame and CPU times are not comparable with a normal one.
+    public var lockDiagnostics: Bool = false
 
     public init(platform: String) {
         self.platform = platform
@@ -85,6 +88,65 @@ public struct BenchSceneResult: Codable, Sendable {
     public var summary: EngineStatsRecordingSummary
     /// The last published snapshot of the scene, for the compositor, hitch and pass details.
     public var lastSnapshot: EngineStatsSnapshot
+    /// Fraction of the recorded frames during which the app was the active (frontmost) app; an
+    /// app that is not frontmost may be scheduled at a lower priority. 1 on platforms where the
+    /// question does not arise.
+    public var activeFraction: Double = 1.0
+    /// CPU cores' worth of work done by every other process on the machine while the scene was
+    /// recorded (macOS; 0 where it is not measured). Above about one core, frame pacing and the
+    /// small CPU times of the light scenes are no longer the benchmark's own.
+    public var otherProcessLoadCores: Double = 0.0
+}
+
+/// CPU time used by the whole machine and by this process up to now, to tell how busy the machine
+/// was with other work while a scene was recorded.
+public struct MachineLoadSample: Sendable {
+    public var wallSeconds: Double
+    public var hostBusySeconds: Double
+    public var selfCPUSeconds: Double
+
+    public static func now() -> MachineLoadSample? {
+        #if os(macOS)
+            var info = host_cpu_load_info()
+            var count = mach_msg_type_number_t(MemoryLayout<host_cpu_load_info>.stride / MemoryLayout<integer_t>.stride)
+            let result = withUnsafeMutablePointer(to: &info) { pointer in
+                pointer.withMemoryRebound(to: integer_t.self, capacity: Int(count)) {
+                    host_statistics(mach_host_self(), HOST_CPU_LOAD_INFO, $0, &count)
+                }
+            }
+            guard result == KERN_SUCCESS else { return nil }
+            // User, system and nice ticks of every CPU; index 2 is idle.
+            let busyTicks = Double(info.cpu_ticks.0) + Double(info.cpu_ticks.1) + Double(info.cpu_ticks.3)
+            let ticksPerSecond = Double(max(1, sysconf(_SC_CLK_TCK)))
+            var usage = rusage()
+            getrusage(RUSAGE_SELF, &usage)
+            let selfSeconds = Double(usage.ru_utime.tv_sec) + Double(usage.ru_utime.tv_usec) / 1e6
+                + Double(usage.ru_stime.tv_sec) + Double(usage.ru_stime.tv_usec) / 1e6
+            return MachineLoadSample(
+                wallSeconds: ProcessInfo.processInfo.systemUptime,
+                hostBusySeconds: busyTicks / ticksPerSecond,
+                selfCPUSeconds: selfSeconds
+            )
+        #else
+            return nil
+        #endif
+    }
+
+    /// CPU cores' worth of work done by other processes between an earlier sample and this one.
+    public func otherProcessLoadCores(since earlier: MachineLoadSample) -> Double {
+        let wall = wallSeconds - earlier.wallSeconds
+        guard wall > 0 else { return 0.0 }
+        let host = hostBusySeconds - earlier.hostBusySeconds
+        let own = selfCPUSeconds - earlier.selfCPUSeconds
+        return max(0.0, (host - own) / wall)
+    }
+}
+
+public extension BenchSceneResult {
+    /// Below this fraction of active frames the report says the app was not frontmost.
+    static let activeFractionRequired = 0.98
+    /// From this load by other processes on, the report says the machine was busy.
+    static let busyMachineCores = 1.0
 }
 
 public struct BenchRunSummary: Codable, Sendable {
@@ -125,10 +187,23 @@ public struct BenchRunSummary: Codable, Sendable {
             let miss = s.deadlineSamples > 0
                 ? String(format: " deadlineMiss %.2f%%", Double(s.missedDeadlines) / Double(s.deadlineSamples) * 100)
                 : ""
+            let lockCalls = s.lockCallsPerFrame.values.reduce(0.0, +)
+            let locks = s.lockCallsPerFrame.isEmpty
+                ? ""
+                : String(
+                    format: " | locks %.0f/frame, contended %d, wait %.2f ms",
+                    lockCalls, s.lockContended.values.reduce(0, +), s.lockWaitMs.values.reduce(0.0, +)
+                )
+            var inactive = scene.activeFraction < BenchSceneResult.activeFractionRequired
+                ? String(format: " | app not active for %.0f%% of the scene", (1.0 - scene.activeFraction) * 100)
+                : ""
+            if scene.otherProcessLoadCores >= BenchSceneResult.busyMachineCores {
+                inactive += String(format: " | MACHINE BUSY: other processes used %.1f cores", scene.otherProcessLoadCores)
+            }
             lines.append(String(
-                format: "  %@: frames %d | mean %.2f p95 %.2f p99 %.2f worst %.2f ms | over budget %d | gpu %.2f ms%@ | thermal %d",
+                format: "  %@: frames %d | mean %.2f p95 %.2f p99 %.2f worst %.2f ms | over budget %d | gpu %.2f ms%@ | thermal %d%@%@",
                 scene.id, s.frames, s.meanFrameMs, s.p95FrameMs, s.p99FrameMs, s.worstFrameMs,
-                s.framesOverBudget, s.meanGPUExecutionMs, miss, s.worstThermalState
+                s.framesOverBudget, s.meanGPUExecutionMs, miss, s.worstThermalState, locks, inactive
             ))
         }
         return lines.joined(separator: "\n")

Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift

@@ -26,6 +26,9 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
         case building(Int)
         case warmup(Int)
         case recording(Int)
+        /// Recording has stopped; waiting for work the scene started (a load in flight, a thread)
+        /// to finish before its entities are destroyed.
+        case settling(Int)
         case tearingDown(Int)
         case finished
     }
@@ -41,6 +44,9 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
     public var sceneOrigin: simd_float3 = .zero
     /// Whether the runner moves the camera along each scene's orbit (off on visionOS).
     public var drivesCamera = true
+    /// Whether the app is the active (frontmost) one, asked once per recorded frame on the update
+    /// thread. Set on macOS, where an app that is not frontmost runs at background priority.
+    public var isAppActive: (() -> Bool)?
     public var onFinished: ((BenchRunSummary) -> Void)?
 
     private let scenes: [BenchScene]
@@ -50,6 +56,9 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
     private var phaseDeadline: Double = 0.0
     private var sceneStart: Double = 0.0
     private var cameraEntity: EntityID?
+    private var recordedFrames = 0
+    private var recordedActiveFrames = 0
+    private var loadAtRecordingStart: MachineLoadSample?
     private let startLock = NSLock()
     private var startRequested = false
     private var started = false
@@ -108,13 +117,14 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
             }
         }
         render.antiAliasing = String(describing: antiAliasingMode)
+        render.lockDiagnostics = EngineLockDiagnostics.isCompiledIn
         summary.render = render
         gameMode = true
         setState(.building(0))
     }
 
     /// Call from the engine's game update callback every frame, on the engine's update thread.
-    public func update(deltaTime _: Float) {
+    public func update(deltaTime: Float) {
         beginRunIfRequested()
         let now = CACurrentMediaTime()
         switch state {
@@ -135,6 +145,7 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
 
         case let .warmup(index):
             driveCamera(scenes[index], elapsed: now - sceneStart)
+            scenes[index].update(deltaTime: deltaTime, elapsed: now - sceneStart)
             setStatus(String(format: "%@: warming up %.0fs", scenes[index].id, phaseDeadline - now))
             if now >= phaseDeadline {
                 EngineStatsMonitor.shared.reset()
@@ -145,14 +156,31 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
                     setStatus("Recording failed: \(error)")
                 }
                 phaseDeadline = now + config.measureSeconds
+                recordedFrames = 0
+                recordedActiveFrames = 0
+                loadAtRecordingStart = MachineLoadSample.now()
                 setState(.recording(index))
             }
 
         case let .recording(index):
             driveCamera(scenes[index], elapsed: now - sceneStart)
+            scenes[index].update(deltaTime: deltaTime, elapsed: now - sceneStart)
+            recordedFrames += 1
+            if isAppActive?() ?? true {
+                recordedActiveFrames += 1
+            }
             setStatus(String(format: "%@: recording %.0fs", scenes[index].id, phaseDeadline - now))
             if now >= phaseDeadline {
-                finishScene(index)
+                stopRecording(index)
+                scenes[index].requestStop()
+                phaseDeadline = now + Self.settleTimeoutSeconds
+                setState(.settling(index))
+            }
+
+        case let .settling(index):
+            setStatus("\(scenes[index].id): finishing")
+            if scenes[index].isQuiescent || now >= phaseDeadline {
+                teardownScene(index)
                 phaseDeadline = now + 0.75
                 setState(.tearingDown(index))
             }
@@ -198,10 +226,19 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
         cameraLookAt(entityId: cameraEntity, eye: eye, target: sceneOrigin + orbit.center, up: simd_float3(0, 1, 0))
     }
 
-    private func finishScene(_ index: Int) {
+    /// Longest the runner waits for a scene to become quiescent before destroying its entities.
+    private static let settleTimeoutSeconds = 5.0
+
+    /// Ends the recording and stores the scene's result. The scene itself keeps running until
+    /// `teardownScene`, so nothing it has in flight is cut off while it is being measured.
+    private func stopRecording(_ index: Int) {
         let scene = scenes[index]
         let recording = stopEngineStatsRecording() ?? EngineStatsRecordingSummary()
         let snapshot = getEngineStatsSnapshot()
+        var otherLoad = 0.0
+        if let start = loadAtRecordingStart, let end = MachineLoadSample.now() {
+            otherLoad = end.otherProcessLoadCores(since: start)
+        }
         if render.viewportWidth == 0 {
             render.viewportWidth = snapshot.compositor.viewTextureWidth
             render.viewportHeight = snapshot.compositor.viewTextureHeight
@@ -216,8 +253,14 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable {
             warmupSeconds: config.warmupSeconds,
             measureSeconds: config.measureSeconds,
             summary: recording,
-            lastSnapshot: snapshot
+            lastSnapshot: snapshot,
+            activeFraction: recordedFrames > 0 ? Double(recordedActiveFrames) / Double(recordedFrames) : 1.0,
+            otherProcessLoadCores: otherLoad
         ))
+    }
+
+    private func teardownScene(_ index: Int) {
+        let scene = scenes[index]
         scene.teardown()
         cameraEntity = nil
         setSceneReady(false)

Examples/PerfBench/Sources/PerfBenchCore/BenchScenes.swift

@@ -36,18 +36,29 @@ public struct BenchCameraOrbit: Sendable {
 
 /// One benchmark scene. `build` creates every entity relative to `origin`; the runner destroys
 /// them afterwards, so `teardown` only has to undo global settings the scene changed. Scenes are
-/// built from the engine's update callback, on the main thread or the XR render thread.
+/// built, updated and torn down from the engine's update callback, on the main thread or the XR
+/// render thread.
 public protocol BenchScene {
     var id: String { get }
     var title: String { get }
     var notes: String { get }
     /// Camera orbit for macOS and iOS. On visionOS the head is the camera and the orbit is ignored.
     var orbit: BenchCameraOrbit { get }
     func build(origin: simd_float3)
+    /// Called once per frame during warm-up and recording, for scenes whose load is game code
+    /// running every frame. `elapsed` counts from the end of `build`.
+    func update(deltaTime: Float, elapsed: Double)
+    /// Recording has ended: stop starting work of the scene's own (loads, threads).
+    func requestStop()
+    /// Whether everything the scene started has finished, so its entities can be destroyed.
+    var isQuiescent: Bool { get }
     func teardown()
 }
 
 public extension BenchScene {
+    func update(deltaTime _: Float, elapsed _: Double) {}
+    func requestStop() {}
+    var isQuiescent: Bool { true }
     func teardown() {}
 }
 
@@ -61,6 +72,9 @@ public enum BenchScenes {
         AnimationScene(),
         StadiumScene(),
         GaussianScene(),
+        LockAPICallsScene(),
+        LockLoadingScene(),
+        LockSecondThreadScene(),
     ]
 
     public static func scenes(withIDs ids: [String]) -> [BenchScene] {