From 94106a430d5b4e4f193d573396cb8c9ac1a59523 Mon Sep 17 00:00:00 2001 From: Javier Segura Date: Sat, 3 Oct 2026 19:27:36 +0200 Subject: [PATCH 1/4] [Feature] Engine lock types with compile-time diagnostics One set of lock types for the engine, so the primitive is chosen in one place and every lock can be measured the same way (docs/proposals/ActorsAndLocks.md): - EngineLock: non-recursive, an os_unfair_lock. - EngineProtected: a value reachable only while holding its lock. - EngineRecursiveLock: an unfair lock with an owner word and a depth, for the few places where re-entry is real. The owner word is read without the lock through C11 atomics (new C target CEngineAtomics; Synchronization.Atomic needs macOS 15 and iOS 18). In a normal build each call compiles down to the bare os_unfair_lock call. Uncontended lock and unlock, release build, M4 Max: os_unfair_lock 1.73 ns, EngineLock 1.74 ns, EngineProtected 1.75 ns, EngineRecursiveLock 2.91 ns, against NSLock 5.88 ns and NSRecursiveLock 11.25 ns (UNTOLD_LOCK_COST=1, EngineLockTests/test_cost_uncontendedLockAndUnlock). Built with the compile-time flag ENGINE_LOCK_DIAGNOSTICS the same types count every acquisition and re-entry, detect contention with a trylock and time the wait and the hold, per named lock, with an optional per source location count (UNTOLD_LOCK_SITES=1). EngineLockDiagnostics reports them; the stats monitor puts the per-frame numbers in EngineStatsSnapshot.locks, the recorder keeps lock calls, hold time, contention and wait per lock name in its summary, and the verbose stats output gains a Locks line. It is a build mode rather than a runtime switch because a frame takes hundreds of thousands of locks. No engine lock uses the new types yet. --- Package.swift | 8 +- Sources/CEngineAtomics/EngineAtomics.c | 12 + .../CEngineAtomics/include/EngineAtomics.h | 31 ++ .../Profiling/EngineLockDiagnostics.swift | 407 ++++++++++++++++++ .../Profiling/EngineStatsFormatter.swift | 17 +- .../Profiling/EngineStatsMonitor.swift | 5 + .../Profiling/EngineStatsRecorder.swift | 24 ++ .../Profiling/EngineStatsSnapshot.swift | 7 +- Sources/UntoldEngine/Utils/EngineLock.swift | 213 +++++++++ Tests/UntoldEngineTests/EngineLockTests.swift | 347 +++++++++++++++ docs/API/UsingProfiler.md | 55 +++ 11 files changed, 1123 insertions(+), 3 deletions(-) create mode 100644 Sources/CEngineAtomics/EngineAtomics.c create mode 100644 Sources/CEngineAtomics/include/EngineAtomics.h create mode 100644 Sources/UntoldEngine/Profiling/EngineLockDiagnostics.swift create mode 100644 Sources/UntoldEngine/Utils/EngineLock.swift create mode 100644 Tests/UntoldEngineTests/EngineLockTests.swift diff --git a/Package.swift b/Package.swift index ecff90d5a..c6534882d 100644 --- a/Package.swift +++ b/Package.swift @@ -84,6 +84,12 @@ let package = Package( .headerSearchPath("."), ] ), + // Word-sized atomics for the engine's lock types (see EngineLock.swift). + .target( + name: "CEngineAtomics", + path: "Sources/CEngineAtomics", + publicHeadersPath: "include" + ), .target( name: "UntoldEngineShaderSupport", path: "Sources/UntoldEngineShaderSupport", @@ -107,7 +113,7 @@ let package = Package( ), .target( name: "UntoldEngine", - dependencies: ["CShaderTypes"], + dependencies: ["CShaderTypes", "CEngineAtomics"], path: "Sources/UntoldEngine", exclude: [ "Shaders", diff --git a/Sources/CEngineAtomics/EngineAtomics.c b/Sources/CEngineAtomics/EngineAtomics.c new file mode 100644 index 000000000..d507b277a --- /dev/null +++ b/Sources/CEngineAtomics/EngineAtomics.c @@ -0,0 +1,12 @@ +// +// EngineAtomics.c +// UntoldEngine +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +// The functions are static inline in the header; this file only gives the target a source. +#include "EngineAtomics.h" diff --git a/Sources/CEngineAtomics/include/EngineAtomics.h b/Sources/CEngineAtomics/include/EngineAtomics.h new file mode 100644 index 000000000..cb7bf6730 --- /dev/null +++ b/Sources/CEngineAtomics/include/EngineAtomics.h @@ -0,0 +1,31 @@ +// +// EngineAtomics.h +// UntoldEngine +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +#ifndef UNTOLD_ENGINE_ATOMICS_H +#define UNTOLD_ENGINE_ATOMICS_H + +#include +#include + +// Word-sized atomic load and store for Swift code that cannot use `Synchronization.Atomic` +// (macOS 15, iOS 18) at the engine's deployment targets. `EngineRecursiveLock` uses them for +// its owner word, which a thread reads without holding the lock to recognise its own re-entry. +// Relaxed ordering is enough there: a thread can only ever read its own identifier back if it +// stored it itself. + +static inline uintptr_t UEAtomicLoadRelaxed(const uintptr_t *_Nonnull address) { + return atomic_load_explicit((const _Atomic(uintptr_t) *)address, memory_order_relaxed); +} + +static inline void UEAtomicStoreRelaxed(uintptr_t *_Nonnull address, uintptr_t value) { + atomic_store_explicit((_Atomic(uintptr_t) *)address, value, memory_order_relaxed); +} + +#endif diff --git a/Sources/UntoldEngine/Profiling/EngineLockDiagnostics.swift b/Sources/UntoldEngine/Profiling/EngineLockDiagnostics.swift new file mode 100644 index 000000000..163d18f1c --- /dev/null +++ b/Sources/UntoldEngine/Profiling/EngineLockDiagnostics.swift @@ -0,0 +1,407 @@ +// +// EngineLockDiagnostics.swift +// UntoldEngine +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +import Foundation +import os + +/// What one lock name did over a period: a frame in `EngineStatsSnapshot.locks`, or everything +/// since the last `EngineLockDiagnostics.reset()` in `EngineLockDiagnostics.snapshot()`. +public struct EngineLockStats: Codable, Sendable, Equatable { + /// The name given to `EngineLock`, `EngineProtected` or `EngineRecursiveLock`. + public var name: String + /// Live lock objects reported under this name. + public var instances: Int = 0 + /// Times the lock was taken, not counting re-entries. + public var acquisitions: Int = 0 + /// Times a thread that already held a recursive lock took it again. + public var reentries: Int = 0 + /// Acquisitions that found the lock held by another thread and had to wait. + public var contended: Int = 0 + /// Time spent waiting in contended acquisitions. + public var waitMs: Double = 0.0 + /// Time the lock was held. The clock ticks every 42 ns on Apple silicon, so this is only + /// meaningful summed over many acquisitions. + public var holdMs: Double = 0.0 + /// Longest single hold since the last `EngineLockDiagnostics.reset()`. + public var maxHoldMs: Double = 0.0 + + public init(name: String) { + self.name = name + } +} + +/// How often one source location took a lock (recorded only with `recordsSites` on). +public struct EngineLockSiteStats: Codable, Sendable, Equatable { + public var name: String + public var file: String + public var line: Int + public var count: Int +} + +/// Counts and timings of the engine's locks, available in builds compiled with +/// `ENGINE_LOCK_DIAGNOSTICS`. In every other build the calls below return nothing and the lock +/// types carry no instrumentation at all. +/// +/// swift build -Xswiftc -DENGINE_LOCK_DIAGNOSTICS +public enum EngineLockDiagnostics { + /// Whether this build was compiled with `ENGINE_LOCK_DIAGNOSTICS`. + public static var isCompiledIn: Bool { + #if ENGINE_LOCK_DIAGNOSTICS + return true + #else + return false + #endif + } + + /// When true, every acquisition is also counted per source location (file and line of the + /// `lock()` or `withLock` call). Costs a dictionary update per acquisition, so it is off by + /// default; `UNTOLD_LOCK_SITES=1` in the environment turns it on from launch. + public nonisolated(unsafe) static var recordsSites: Bool = + ProcessInfo.processInfo.environment["UNTOLD_LOCK_SITES"] == "1" + + /// Totals per lock name since the last `reset()`, most active first. + public static func snapshot() -> [EngineLockStats] { + #if ENGINE_LOCK_DIAGNOSTICS + os_unfair_lock_lock(registryLock) + let totals = totalsLocked() + os_unfair_lock_unlock(registryLock) + return totals.map { stats(name: $0.key, instances: $0.value.instances, counters: $0.value.counters) } + .sorted(by: moreActive) + #else + return [] + #endif + } + + /// What every lock name did since the previous call, most active first. The stats monitor + /// calls this once per frame to fill `EngineStatsSnapshot.locks`. + public static func consumeFrameDelta() -> [EngineLockStats] { + #if ENGINE_LOCK_DIAGNOSTICS + os_unfair_lock_lock(registryLock) + let totals = totalsLocked() + var result: [EngineLockStats] = [] + for (name, entry) in totals { + var delta = entry.counters + if let base = registry.frameBase[name] { + delta.subtract(base) + } + if delta.acquisitions == 0, delta.reentries == 0 { + continue + } + result.append(stats(name: name, instances: entry.instances, counters: delta)) + } + registry.frameBase = totals.mapValues(\.counters) + os_unfair_lock_unlock(registryLock) + return result.sorted(by: moreActive) + #else + return [] + #endif + } + + /// Per source location counts since the last `reset()`, most active first. Empty unless + /// `recordsSites` was on while the locks were taken. + public static func sites(top: Int = 40) -> [EngineLockSiteStats] { + #if ENGINE_LOCK_DIAGNOSTICS + os_unfair_lock_lock(registryLock) + var merged: [SiteName: UInt64] = registry.retiredSites + for record in registry.live.values { + let name = record.name.description + let copy: [EngineLockSite: UInt64]? = record.whileHeld { record.sites } + for (site, count) in copy ?? [:] { + merged[SiteName(name: name, file: site.fileName, line: site.line), default: 0] += count + } + } + os_unfair_lock_unlock(registryLock) + return merged + .map { EngineLockSiteStats(name: $0.key.name, file: $0.key.file, line: Int($0.key.line), count: Int($0.value)) } + .sorted { $0.count != $1.count ? $0.count > $1.count : ($0.file, $0.line) < ($1.file, $1.line) } + .prefix(max(0, top)) + .map { $0 } + #else + return [] + #endif + } + + /// Zeroes every counter. Call it from a point where the calling thread holds no engine lock. + public static func reset() { + #if ENGINE_LOCK_DIAGNOSTICS + os_unfair_lock_lock(registryLock) + for record in registry.live.values { + let cleared: Void? = record.whileHeld { + record.counters = EngineLockCounters() + record.sites.removeAll(keepingCapacity: true) + } + if cleared == nil { + // Held for the whole retry window: zero the plain counters anyway. A racing + // update may survive; that is acceptable for a diagnostics counter. + record.counters = EngineLockCounters() + } + } + registry.retired.removeAll() + registry.retiredSites.removeAll() + registry.frameBase.removeAll() + os_unfair_lock_unlock(registryLock) + #endif + } + + /// A table of `snapshot()` (and of `sites()` when sites were recorded), with counts divided + /// by `divisor`, for example the number of frames the counters cover. + public static func report(per divisor: Int = 1, unit: String = "frame", top: Int = 24) -> String { + #if ENGINE_LOCK_DIAGNOSTICS + let d = Double(max(1, divisor)) + var lines: [String] = [] + let locks = snapshot() + let total = locks.reduce(0) { $0 + $1.acquisitions + $1.reentries } + lines.append(String(format: "Engine locks: %.1f lock calls per %@", Double(total) / d, unit)) + lines.append(" " + "lock".padding(toLength: 34, withPad: " ", startingAt: 0) + + " taken reentries contended wait ms hold ms max hold ms instances") + for lock in locks.prefix(max(0, top)) { + lines.append(" " + lock.name.padding(toLength: 34, withPad: " ", startingAt: 0) + String( + format: " %10.1f %10.1f %10d %10.3f %10.3f %12.4f %10d", + Double(lock.acquisitions) / d, Double(lock.reentries) / d, lock.contended, + lock.waitMs, lock.holdMs / d, lock.maxHoldMs, lock.instances + )) + } + let siteRows = sites(top: top) + if !siteRows.isEmpty { + lines.append(" by source location (calls per \(unit))") + for site in siteRows { + lines.append(String(format: " %10.1f ", Double(site.count) / d) + "\(site.file):\(site.line) [\(site.name)]") + } + } + return lines.joined(separator: "\n") + #else + return "Engine lock diagnostics are not compiled in (build with -DENGINE_LOCK_DIAGNOSTICS)." + #endif + } +} + +#if ENGINE_LOCK_DIAGNOSTICS + + struct EngineLockCounters: Sendable { + var acquisitions: UInt64 = 0 + var reentries: UInt64 = 0 + var contended: UInt64 = 0 + var waitTicks: UInt64 = 0 + var holdTicks: UInt64 = 0 + var maxHoldTicks: UInt64 = 0 + + mutating func add(_ other: EngineLockCounters) { + acquisitions &+= other.acquisitions + reentries &+= other.reentries + contended &+= other.contended + waitTicks &+= other.waitTicks + holdTicks &+= other.holdTicks + maxHoldTicks = max(maxHoldTicks, other.maxHoldTicks) + } + + /// Subtracts an earlier reading of the same counters. The maximum is not a sum and stays. + mutating func subtract(_ base: EngineLockCounters) { + acquisitions = acquisitions >= base.acquisitions ? acquisitions - base.acquisitions : 0 + reentries = reentries >= base.reentries ? reentries - base.reentries : 0 + contended = contended >= base.contended ? contended - base.contended : 0 + waitTicks = waitTicks >= base.waitTicks ? waitTicks - base.waitTicks : 0 + holdTicks = holdTicks >= base.holdTicks ? holdTicks - base.holdTicks : 0 + } + } + + struct EngineLockSite: Hashable { + /// `#fileID` literals are static, so the address identifies the file within a module. + let file: UnsafePointer + let fileLength: Int + let line: UInt + + var fileName: String { + String(decoding: UnsafeBufferPointer(start: file, count: fileLength), as: UTF8.self) + } + } + + /// Per-lock counters. Every field is written only by the thread that holds the lock the + /// record belongs to, so the lock itself protects them. + @usableFromInline + final class EngineLockRecord: @unchecked Sendable { + let name: StaticString + let unfairLock: UnsafeMutablePointer + var counters = EngineLockCounters() + var holdStart: UInt64 = 0 + var sites: [EngineLockSite: UInt64] = [:] + + init(name: StaticString, lock: UnsafeMutablePointer) { + self.name = name + unfairLock = lock + } + + @usableFromInline + func lock(_ unfairLock: UnsafeMutablePointer, file: StaticString, line: UInt) { + if os_unfair_lock_trylock(unfairLock) { + holdStart = mach_absolute_time() + } else { + let waitStart = mach_absolute_time() + os_unfair_lock_lock(unfairLock) + let now = mach_absolute_time() + counters.contended &+= 1 + counters.waitTicks &+= now &- waitStart + holdStart = now + } + counters.acquisitions &+= 1 + if EngineLockDiagnostics.recordsSites { + noteSite(file: file, line: line) + } + } + + @usableFromInline + func tryLock(_ unfairLock: UnsafeMutablePointer, file: StaticString, line: UInt) -> Bool { + guard os_unfair_lock_trylock(unfairLock) else { return false } + holdStart = mach_absolute_time() + counters.acquisitions &+= 1 + if EngineLockDiagnostics.recordsSites { + noteSite(file: file, line: line) + } + return true + } + + @usableFromInline + func unlock(_ unfairLock: UnsafeMutablePointer) { + let held = mach_absolute_time() &- holdStart + counters.holdTicks &+= held + if held > counters.maxHoldTicks { + counters.maxHoldTicks = held + } + os_unfair_lock_unlock(unfairLock) + } + + /// A thread that already holds the (recursive) lock took it again. + @usableFromInline + func reentered(file: StaticString, line: UInt) { + counters.reentries &+= 1 + if EngineLockDiagnostics.recordsSites { + noteSite(file: file, line: line) + } + } + + private func noteSite(file: StaticString, line: UInt) { + guard file.hasPointerRepresentation else { return } + sites[EngineLockSite(file: file.utf8Start, fileLength: file.utf8CodeUnitCount, line: line), default: 0] &+= 1 + } + + /// Reads the counters. Takes the lock when it is free; when it is not (another thread + /// holds it, or the caller does), reads the plain words as they are. + func readCounters() -> EngineLockCounters { + let locked = os_unfair_lock_trylock(unfairLock) + let copy = counters + if locked { + os_unfair_lock_unlock(unfairLock) + } + return copy + } + + /// Runs `body` holding the lock, without counting the acquisition. Retries for up to + /// about 100 ms and returns nil if the lock stayed held, which also covers a caller + /// that holds it itself (an unfair lock cannot tell and would trap on a blocking lock). + func whileHeld(_ body: () -> Result) -> Result? { + for _ in 0 ..< 2000 { + if os_unfair_lock_trylock(unfairLock) { + defer { os_unfair_lock_unlock(unfairLock) } + return body() + } + usleep(50) + } + return nil + } + } + + extension EngineLockDiagnostics { + struct SiteName: Hashable { + let name: String + let file: String + let line: UInt + } + + struct Registry { + var live: [ObjectIdentifier: EngineLockRecord] = [:] + /// Counters of locks that were deallocated, by name. + var retired: [String: EngineLockCounters] = [:] + var retiredSites: [SiteName: UInt64] = [:] + /// Totals at the previous `consumeFrameDelta()`. + var frameBase: [String: EngineLockCounters] = [:] + } + + /// Guards `registry`. A raw unfair lock: the registry cannot be measured by itself. + nonisolated(unsafe) static let registryLock: UnsafeMutablePointer = { + let pointer = UnsafeMutablePointer.allocate(capacity: 1) + pointer.initialize(to: os_unfair_lock()) + return pointer + }() + + nonisolated(unsafe) static var registry = Registry() + + static let millisecondsPerTick: Double = { + var info = mach_timebase_info_data_t() + mach_timebase_info(&info) + return Double(info.numer) / Double(info.denom) / 1_000_000.0 + }() + + @usableFromInline + static func register(name: StaticString, lock: UnsafeMutablePointer) -> EngineLockRecord { + let record = EngineLockRecord(name: name, lock: lock) + os_unfair_lock_lock(registryLock) + registry.live[ObjectIdentifier(record)] = record + os_unfair_lock_unlock(registryLock) + return record + } + + /// Called from the lock's deinit, so nothing else can hold or take the lock any more. + @usableFromInline + static func retire(_ record: EngineLockRecord) { + let name = record.name.description + os_unfair_lock_lock(registryLock) + registry.live.removeValue(forKey: ObjectIdentifier(record)) + registry.retired[name, default: EngineLockCounters()].add(record.counters) + for (site, count) in record.sites { + registry.retiredSites[SiteName(name: name, file: site.fileName, line: site.line), default: 0] += count + } + os_unfair_lock_unlock(registryLock) + } + + /// Totals by name. Call with `registryLock` held. + static func totalsLocked() -> [String: (counters: EngineLockCounters, instances: Int)] { + var totals: [String: (counters: EngineLockCounters, instances: Int)] = [:] + for (name, counters) in registry.retired { + totals[name] = (counters, 0) + } + for record in registry.live.values { + let name = record.name.description + var entry = totals[name] ?? (EngineLockCounters(), 0) + entry.counters.add(record.readCounters()) + entry.instances += 1 + totals[name] = entry + } + return totals + } + + static func stats(name: String, instances: Int, counters: EngineLockCounters) -> EngineLockStats { + var result = EngineLockStats(name: name) + result.instances = instances + result.acquisitions = Int(clamping: counters.acquisitions) + result.reentries = Int(clamping: counters.reentries) + result.contended = Int(clamping: counters.contended) + result.waitMs = Double(counters.waitTicks) * millisecondsPerTick + result.holdMs = Double(counters.holdTicks) * millisecondsPerTick + result.maxHoldMs = Double(counters.maxHoldTicks) * millisecondsPerTick + return result + } + + static func moreActive(_ lhs: EngineLockStats, _ rhs: EngineLockStats) -> Bool { + let l = lhs.acquisitions + lhs.reentries + let r = rhs.acquisitions + rhs.reentries + return l != r ? l > r : lhs.name < rhs.name + } + } + +#endif diff --git a/Sources/UntoldEngine/Profiling/EngineStatsFormatter.swift b/Sources/UntoldEngine/Profiling/EngineStatsFormatter.swift index 3debc1484..9aaf7ddd1 100644 --- a/Sources/UntoldEngine/Profiling/EngineStatsFormatter.swift +++ b/Sources/UntoldEngine/Profiling/EngineStatsFormatter.swift @@ -58,6 +58,7 @@ private func expandedEngineStatsString(_ snapshot: EngineStatsSnapshot) -> Strin let pressure = snapshot.memory.isUnderPressure ? " PRESSURE" : "" let compositorLine = compositorStatsLine(snapshot) let gpuPassLine = gpuPassStatsLine(snapshot) + let lockLine = lockStatsLine(snapshot) let hitchLine = hitchStatsLine(snapshot) let gpuAllocMB = formatMB(snapshot.memory.gpuAllocatedBytes) let availableMB = snapshot.memory.availableMemoryBytes > 0 ? " | avail \(formatMB(snapshot.memory.availableMemoryBytes))mb" : "" @@ -72,7 +73,7 @@ private func expandedEngineStatsString(_ snapshot: EngineStatsSnapshot) -> Strin TileReps: resident full/lod/hlod \(snapshot.streaming.residentFullTileRepresentations)/\(snapshot.streaming.residentLODRepresentations)/\(snapshot.streaming.residentHLODRepresentations) | visible full/lod/hlod \(snapshot.streaming.visibleFullTileRepresentations)/\(snapshot.streaming.visibleLODRepresentations)/\(snapshot.streaming.visibleHLODRepresentations) | overlap visible full+lod/full+hlod/lod+hlod \(snapshot.streaming.fullAndLODVisibleOverlapTiles)/\(snapshot.streaming.fullAndHLODVisibleOverlapTiles)/\(snapshot.streaming.lodAndHLODVisibleOverlapTiles) residentFull+fallback \(snapshot.streaming.fullAndFallbackResidentOverlapTiles) | fades \(snapshot.streaming.activeTileRepresentationFades) waiting \(snapshot.streaming.waitingTileRepresentationFades) TileRenderCost: visible full/lod/hlod \(snapshot.render.tileFullVisibleInstances)/\(snapshot.render.tileLODVisibleInstances)/\(snapshot.render.tileHLODVisibleInstances) | draws full/lod/hlod \(snapshot.render.tileFullDrawsEstimate)/\(snapshot.render.tileLODDrawsEstimate)/\(snapshot.render.tileHLODDrawsEstimate) | tris full/lod/hlod \(snapshot.render.tileFullTrianglesEstimate)/\(snapshot.render.tileLODTrianglesEstimate)/\(snapshot.render.tileHLODTrianglesEstimate) Batching: groups \(snapshot.batching.batchGroupCount) | batchedMeshes \(snapshot.batching.batchedMeshCount) | dirty \(snapshot.batching.dirtyCellsBeforePrune)→\(snapshot.batching.dirtyCellsAfterPrune) | defWork \(snapshot.batching.deferredByWorkBudget) skipComplex \(snapshot.batching.skippedByComplexityGuard) | dispatched \(snapshot.batching.dispatchedBuilds)→\(snapshot.batching.lastRebuildOutputBatchCount) groups | rebuilds/s \(snapshot.batching.rebuildsThisSecond) | rebuildMs \(formatMs(snapshot.batching.lastRebuildCostMs)) - Memory: mesh \(meshMB)/\(meshBudgetMB)mb | tex \(texMB)/\(texBudgetMB)mb | total \(memPct) | entities \(snapshot.memory.trackedEntityCount)\(pressure) | gpuAlloc \(gpuAllocMB)mb\(availableMB) | thermal \(snapshot.memory.thermalStateName)\(hitchLine)\(compositorLine)\(gpuPassLine) + Memory: mesh \(meshMB)/\(meshBudgetMB)mb | tex \(texMB)/\(texBudgetMB)mb | total \(memPct) | entities \(snapshot.memory.trackedEntityCount)\(pressure) | gpuAlloc \(gpuAllocMB)mb\(availableMB) | thermal \(snapshot.memory.thermalStateName)\(hitchLine)\(compositorLine)\(gpuPassLine)\(lockLine) """ } @@ -106,6 +107,20 @@ private func gpuPassStatsLine(_ snapshot: EngineStatsSnapshot) -> String { return "\nGPU passes (\(g.passes.count), sum \(formatMs(g.totalMs))ms): \(entries)" } +/// One line with the busiest engine locks of the frame, prefixed with a newline. Empty unless the +/// build was compiled with `ENGINE_LOCK_DIAGNOSTICS`. +private func lockStatsLine(_ snapshot: EngineStatsSnapshot) -> String { + guard !snapshot.locks.isEmpty else { return "" } + let calls = snapshot.locks.reduce(0) { $0 + $1.acquisitions + $1.reentries } + let contended = snapshot.locks.reduce(0) { $0 + $1.contended } + let waitMs = snapshot.locks.reduce(0.0) { $0 + $1.waitMs } + let holdMs = snapshot.locks.reduce(0.0) { $0 + $1.holdMs } + let entries = snapshot.locks.prefix(6).map { lock in + "\(lock.name) \(lock.acquisitions + lock.reentries)" + }.joined(separator: " | ") + return "\nLocks: \(calls) calls | contended \(contended) | wait \(formatMs(waitMs))ms | held \(formatMs(holdMs))ms | \(entries)" +} + /// One line of Compositor Services frame accounting, prefixed with a newline so it can be appended /// to the expanded block. Empty when the frame was not rendered through Compositor Services. private func compositorStatsLine(_ snapshot: EngineStatsSnapshot) -> String { diff --git a/Sources/UntoldEngine/Profiling/EngineStatsMonitor.swift b/Sources/UntoldEngine/Profiling/EngineStatsMonitor.swift index e1155e8f2..f96b41ae1 100644 --- a/Sources/UntoldEngine/Profiling/EngineStatsMonitor.swift +++ b/Sources/UntoldEngine/Profiling/EngineStatsMonitor.swift @@ -322,6 +322,11 @@ public final class EngineStatsMonitor: @unchecked Sendable { currentSnapshot.compositor.deadlineSampleCount = _deadlineSampleCount currentSnapshot.compositor.missingAnchorCount = _missingAnchorCount + #if ENGINE_LOCK_DIAGNOSTICS + // What every named engine lock did since the previous frame was completed. + currentSnapshot.locks = EngineLockDiagnostics.consumeFrameDelta() + #endif + // Update 30-frame rolling average for CPU frame time let frameMs = currentSnapshot.timing.frameTotalMs _frameMsBuffer[_frameMsBufferIndex] = frameMs diff --git a/Sources/UntoldEngine/Profiling/EngineStatsRecorder.swift b/Sources/UntoldEngine/Profiling/EngineStatsRecorder.swift index cf619c097..49efe356a 100644 --- a/Sources/UntoldEngine/Profiling/EngineStatsRecorder.swift +++ b/Sources/UntoldEngine/Profiling/EngineStatsRecorder.swift @@ -49,6 +49,15 @@ public struct EngineStatsRecordingSummary: Codable, Equatable, Sendable { /// Mean of the per-frame CPU timing fields (`EngineTimingStats` and the compositor phases), /// keyed by field name: what a CPU-side optimization changes. public var timingMeanMs: [String: Double] = [:] + /// Lock calls per frame by lock name (acquisitions plus re-entries), averaged over the run. + /// Empty unless the build was compiled with `ENGINE_LOCK_DIAGNOSTICS`; so are the three below. + public var lockCallsPerFrame: [String: Double] = [:] + /// Time each lock name was held per frame, averaged over the run. + public var lockHoldMsPerFrame: [String: Double] = [:] + /// Acquisitions that had to wait for another thread, summed over the run. + public var lockContended: [String: Int] = [:] + /// Time spent waiting in those acquisitions, summed over the run. + public var lockWaitMs: [String: Double] = [:] public var worstThermalState: Int = 0 public var peakGPUAllocatedBytes: Int = 0 @@ -85,6 +94,7 @@ public final class EngineStatsRecorder: @unchecked Sendable { private var gpuPassMins: [String: Double] = [:] private var timingSums: [String: Double] = [:] private var timingSamples = 0 + private var lockSums: [String: (calls: Int, holdMs: Double, contended: Int, waitMs: Double)] = [:] private var firstTimestamp: Double? private var lastTimestamp: Double = 0.0 private var lastWrittenSecond: Double = -1.0 @@ -167,6 +177,14 @@ public final class EngineStatsRecorder: @unchecked Sendable { timingSums[name, default: 0.0] += value } timingSamples += 1 + for lock in snapshot.locks { + var entry = lockSums[lock.name] ?? (0, 0.0, 0, 0.0) + entry.calls += lock.acquisitions + lock.reentries + entry.holdMs += lock.holdMs + entry.contended += lock.contended + entry.waitMs += lock.waitMs + lockSums[lock.name] = entry + } if snapshot.timestampSeconds > 0 { if firstTimestamp == nil { firstTimestamp = snapshot.timestampSeconds @@ -208,6 +226,12 @@ public final class EngineStatsRecorder: @unchecked Sendable { for (name, sum) in timingSums { result.timingMeanMs[name] = sum / Double(timingSamples) } + for (name, entry) in lockSums { + result.lockCallsPerFrame[name] = Double(entry.calls) / Double(timingSamples) + result.lockHoldMsPerFrame[name] = entry.holdMs / Double(timingSamples) + result.lockContended[name] = entry.contended + result.lockWaitMs[name] = entry.waitMs + } } result.worstThermalState = lastSnapshotMaxThermal result.peakGPUAllocatedBytes = peakGPUAllocated diff --git a/Sources/UntoldEngine/Profiling/EngineStatsSnapshot.swift b/Sources/UntoldEngine/Profiling/EngineStatsSnapshot.swift index b38ce54d5..209e78216 100644 --- a/Sources/UntoldEngine/Profiling/EngineStatsSnapshot.swift +++ b/Sources/UntoldEngine/Profiling/EngineStatsSnapshot.swift @@ -500,6 +500,9 @@ public struct EngineStatsSnapshot: Codable, Sendable { public var gpuPasses: GPUPassTimingSnapshot = .init() /// Frame-time distribution and over-budget counts since the monitor was reset. public var hitches: EngineHitchStats = .init() + /// What each named engine lock did during the frame, most active first. Empty unless the + /// build was compiled with `ENGINE_LOCK_DIAGNOSTICS` (see `EngineLockDiagnostics`). + public var locks: [EngineLockStats] = [] public init( frameIndex: UInt64 = 0, @@ -512,7 +515,8 @@ public struct EngineStatsSnapshot: Codable, Sendable { memory: EngineMemoryStats = .init(), compositor: EngineCompositorStats = .init(), gpuPasses: GPUPassTimingSnapshot = .init(), - hitches: EngineHitchStats = .init() + hitches: EngineHitchStats = .init(), + locks: [EngineLockStats] = [] ) { self.frameIndex = frameIndex self.timestampSeconds = timestampSeconds @@ -525,6 +529,7 @@ public struct EngineStatsSnapshot: Codable, Sendable { self.compositor = compositor self.gpuPasses = gpuPasses self.hitches = hitches + self.locks = locks } } diff --git a/Sources/UntoldEngine/Utils/EngineLock.swift b/Sources/UntoldEngine/Utils/EngineLock.swift new file mode 100644 index 000000000..b587aae7f --- /dev/null +++ b/Sources/UntoldEngine/Utils/EngineLock.swift @@ -0,0 +1,213 @@ +// +// EngineLock.swift +// UntoldEngine +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +import CEngineAtomics +import Foundation +import os + +// The engine's lock types. +// +// Every engine lock is one of the three types below, so the primitive is chosen in one place and +// every lock can be measured the same way. In a normal build each call compiles down to the bare +// `os_unfair_lock` call and nothing else. Built with `ENGINE_LOCK_DIAGNOSTICS` (a compile-time +// flag, see docs/API/UsingProfiler.md), every acquisition is also counted and timed per named +// lock, and `EngineLockDiagnostics` reports the result. +// +// The flag is a build mode rather than a runtime switch on purpose: a frame takes hundreds of +// thousands of locks, so even a one-nanosecond runtime check would cost a measurable part of it. +// +// Rules (docs/proposals/ActorsAndLocks.md): `EngineLock` or `EngineProtected` by default; +// `EngineRecursiveLock` only where re-entry is real, and never on a per-entity path. None of +// them may be held across a suspension point. + +/// A non-recursive lock for engine state. Locking it twice from the same thread is a programming +/// error and traps. +public final class EngineLock: @unchecked Sendable { + /// Name the lock is reported under by `EngineLockDiagnostics`. Locks that guard the same kind + /// of state share a name and are reported together. + public let name: StaticString + + @usableFromInline let unfairLock: UnsafeMutablePointer + #if ENGINE_LOCK_DIAGNOSTICS + @usableFromInline let record: EngineLockRecord + #endif + + public init(_ name: StaticString) { + self.name = name + unfairLock = .allocate(capacity: 1) + unfairLock.initialize(to: os_unfair_lock()) + #if ENGINE_LOCK_DIAGNOSTICS + record = EngineLockDiagnostics.register(name: name, lock: unfairLock) + #endif + } + + deinit { + #if ENGINE_LOCK_DIAGNOSTICS + EngineLockDiagnostics.retire(record) + #endif + unfairLock.deinitialize(count: 1) + unfairLock.deallocate() + } + + @inlinable @inline(__always) + public func lock(file: StaticString = #fileID, line: UInt = #line) { + #if ENGINE_LOCK_DIAGNOSTICS + record.lock(unfairLock, file: file, line: line) + #else + os_unfair_lock_lock(unfairLock) + #endif + } + + @inlinable @inline(__always) + public func unlock() { + #if ENGINE_LOCK_DIAGNOSTICS + record.unlock(unfairLock) + #else + os_unfair_lock_unlock(unfairLock) + #endif + } + + /// Takes the lock if it is free. Returns whether it was taken. + @inlinable @inline(__always) + public func tryLock(file: StaticString = #fileID, line: UInt = #line) -> Bool { + #if ENGINE_LOCK_DIAGNOSTICS + return record.tryLock(unfairLock, file: file, line: line) + #else + return os_unfair_lock_trylock(unfairLock) + #endif + } + + @inlinable @inline(__always) + public func withLock( + file: StaticString = #fileID, + line: UInt = #line, + _ body: () throws -> Result + ) rethrows -> Result { + lock(file: file, line: line) + defer { unlock() } + return try body() + } +} + +/// A value that can only be reached while holding its lock. +public final class EngineProtected: @unchecked Sendable { + @usableFromInline let guardLock: EngineLock + /// Kept behind a pointer so the access inside `withLock` carries no dynamic exclusivity check. + @usableFromInline let state: UnsafeMutablePointer + + public init(_ name: StaticString, _ initialState: State) { + guardLock = EngineLock(name) + state = .allocate(capacity: 1) + state.initialize(to: initialState) + } + + deinit { + state.deinitialize(count: 1) + state.deallocate() + } + + @inlinable @inline(__always) + public func withLock( + file: StaticString = #fileID, + line: UInt = #line, + _ body: (inout State) throws -> Result + ) rethrows -> Result { + guardLock.lock(file: file, line: line) + defer { guardLock.unlock() } + return try body(&state.pointee) + } +} + +/// A lock the thread that holds it may take again. Each `lock()` needs its own `unlock()`. +/// +/// Costs a thread-identity read more than `EngineLock` on every call; use it only where code +/// that already holds the lock really calls back into code that takes it. +public final class EngineRecursiveLock: @unchecked Sendable { + public let name: StaticString + + @usableFromInline let unfairLock: UnsafeMutablePointer + /// Identifier of the thread holding the lock, or zero. Read without the lock (atomically) to + /// recognise a re-entry: a thread can only read its own identifier back if it stored it. + @usableFromInline let owner: UnsafeMutablePointer + /// Nesting depth; only touched by the thread that holds the lock. + @usableFromInline let depth: UnsafeMutablePointer + #if ENGINE_LOCK_DIAGNOSTICS + @usableFromInline let record: EngineLockRecord + #endif + + public init(_ name: StaticString) { + self.name = name + unfairLock = .allocate(capacity: 1) + unfairLock.initialize(to: os_unfair_lock()) + owner = .allocate(capacity: 1) + owner.initialize(to: 0) + depth = .allocate(capacity: 1) + depth.initialize(to: 0) + #if ENGINE_LOCK_DIAGNOSTICS + record = EngineLockDiagnostics.register(name: name, lock: unfairLock) + #endif + } + + deinit { + #if ENGINE_LOCK_DIAGNOSTICS + EngineLockDiagnostics.retire(record) + #endif + unfairLock.deinitialize(count: 1) + unfairLock.deallocate() + owner.deinitialize(count: 1) + owner.deallocate() + depth.deinitialize(count: 1) + depth.deallocate() + } + + @inlinable @inline(__always) + public func lock(file: StaticString = #fileID, line: UInt = #line) { + let current = UInt(bitPattern: pthread_self()) + if UEAtomicLoadRelaxed(owner) == current { + depth.pointee &+= 1 + #if ENGINE_LOCK_DIAGNOSTICS + record.reentered(file: file, line: line) + #endif + return + } + #if ENGINE_LOCK_DIAGNOSTICS + record.lock(unfairLock, file: file, line: line) + #else + os_unfair_lock_lock(unfairLock) + #endif + UEAtomicStoreRelaxed(owner, current) + depth.pointee = 1 + } + + @inlinable @inline(__always) + public func unlock() { + let remaining = depth.pointee &- 1 + depth.pointee = remaining + if remaining == 0 { + UEAtomicStoreRelaxed(owner, 0) + #if ENGINE_LOCK_DIAGNOSTICS + record.unlock(unfairLock) + #else + os_unfair_lock_unlock(unfairLock) + #endif + } + } + + @inlinable @inline(__always) + public func withLock( + file: StaticString = #fileID, + line: UInt = #line, + _ body: () throws -> Result + ) rethrows -> Result { + lock(file: file, line: line) + defer { unlock() } + return try body() + } +} diff --git a/Tests/UntoldEngineTests/EngineLockTests.swift b/Tests/UntoldEngineTests/EngineLockTests.swift new file mode 100644 index 000000000..ff843ab2d --- /dev/null +++ b/Tests/UntoldEngineTests/EngineLockTests.swift @@ -0,0 +1,347 @@ +// +// EngineLockTests.swift +// UntoldEngine +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +import Foundation +import os +@testable import UntoldEngine +import XCTest + +private final class Counter: @unchecked Sendable { + var value = 0 +} + +private let threads = 8 +private let iterations = 20000 + +final class EngineLockTests: XCTestCase { + // MARK: - Behaviour (every build) + + func test_engineLock_excludesOtherThreads() { + let lock = EngineLock("Test.exclusion") + let counter = Counter() + DispatchQueue.concurrentPerform(iterations: threads) { _ in + for _ in 0 ..< iterations { + lock.lock() + counter.value += 1 + lock.unlock() + } + } + XCTAssertEqual(counter.value, threads * iterations) + } + + func test_engineLock_withLockReturnsTheBodyResultAndReleasesOnThrow() { + struct Failure: Error {} + let lock = EngineLock("Test.withLock") + XCTAssertEqual(lock.withLock { 7 }, 7) + XCTAssertThrowsError(try lock.withLock { throw Failure() }) + // Released by the throwing call: taking it again must not deadlock. + XCTAssertTrue(lock.tryLock()) + lock.unlock() + } + + func test_engineLock_tryLockFailsWhileAnotherThreadHoldsIt() { + let lock = EngineLock("Test.tryLock") + lock.lock() + let taken = Counter() + let done = DispatchSemaphore(value: 0) + Thread.detachNewThread { + if lock.tryLock() { + taken.value = 1 + lock.unlock() + } + done.signal() + } + done.wait() + XCTAssertEqual(taken.value, 0) + lock.unlock() + XCTAssertTrue(lock.tryLock()) + lock.unlock() + } + + func test_engineProtected_serialisesMutations() { + let state = EngineProtected<[Int: Int]>("Test.protected", [:]) + DispatchQueue.concurrentPerform(iterations: threads) { thread in + for _ in 0 ..< iterations { + state.withLock { $0[thread, default: 0] += 1 } + } + } + let snapshot = state.withLock { $0 } + XCTAssertEqual(snapshot.count, threads) + XCTAssertTrue(snapshot.values.allSatisfy { $0 == iterations }) + } + + func test_recursiveLock_sameThreadMayReenter() { + let lock = EngineRecursiveLock("Test.recursive.reenter") + let value: Int = lock.withLock { + lock.withLock { + lock.lock() + defer { lock.unlock() } + return 3 + } + } + XCTAssertEqual(value, 3) + } + + func test_recursiveLock_staysHeldUntilTheOutermostUnlock() { + let lock = EngineRecursiveLock("Test.recursive.outermost") + let entered = Counter() + let done = DispatchSemaphore(value: 0) + + lock.lock() + lock.lock() + Thread.detachNewThread { + lock.lock() + entered.value = 1 + lock.unlock() + done.signal() + } + Thread.sleep(forTimeInterval: 0.05) + XCTAssertEqual(entered.value, 0, "taken by another thread at depth 2") + lock.unlock() + Thread.sleep(forTimeInterval: 0.05) + XCTAssertEqual(entered.value, 0, "taken by another thread at depth 1") + lock.unlock() + XCTAssertEqual(done.wait(timeout: .now() + 5), .success) + XCTAssertEqual(entered.value, 1) + } + + func test_recursiveLock_excludesOtherThreadsWhileNested() { + let lock = EngineRecursiveLock("Test.recursive.exclusion") + let counter = Counter() + DispatchQueue.concurrentPerform(iterations: threads) { _ in + for _ in 0 ..< iterations { + lock.lock() + lock.lock() + counter.value += 1 + lock.unlock() + counter.value += 1 + lock.unlock() + } + } + XCTAssertEqual(counter.value, 2 * threads * iterations) + } + + // MARK: - Diagnostics + + #if ENGINE_LOCK_DIAGNOSTICS + + private func stats(_ name: String) -> EngineLockStats? { + EngineLockDiagnostics.snapshot().first { $0.name == name } + } + + func test_diagnostics_countAcquisitionsAndReentries() throws { + XCTAssertTrue(EngineLockDiagnostics.isCompiledIn) + let lock = EngineLock("Test.diag.count") + let recursive = EngineRecursiveLock("Test.diag.reentry") + for _ in 0 ..< 100 { + lock.lock() + lock.unlock() + recursive.lock() + recursive.lock() + recursive.lock() + recursive.unlock() + recursive.unlock() + recursive.unlock() + } + let plain = try XCTUnwrap(stats("Test.diag.count")) + XCTAssertEqual(plain.acquisitions, 100) + XCTAssertEqual(plain.reentries, 0) + XCTAssertEqual(plain.contended, 0) + XCTAssertEqual(plain.instances, 1) + let nested = try XCTUnwrap(stats("Test.diag.reentry")) + XCTAssertEqual(nested.acquisitions, 100) + XCTAssertEqual(nested.reentries, 200) + } + + func test_diagnostics_measureWaitAndHoldUnderContention() throws { + let lock = EngineLock("Test.diag.contention") + let holding = DispatchSemaphore(value: 0) + let done = DispatchSemaphore(value: 0) + Thread.detachNewThread { + lock.lock() + holding.signal() + Thread.sleep(forTimeInterval: 0.05) + lock.unlock() + done.signal() + } + holding.wait() + lock.lock() + lock.unlock() + done.wait() + let result = try XCTUnwrap(stats("Test.diag.contention")) + XCTAssertEqual(result.acquisitions, 2) + XCTAssertEqual(result.contended, 1) + XCTAssertGreaterThan(result.waitMs, 20.0) + XCTAssertGreaterThan(result.holdMs, 40.0) + XCTAssertGreaterThan(result.maxHoldMs, 40.0) + } + + func test_diagnostics_locksSharingANameAreReportedTogetherAndSurviveDeallocation() throws { + var first: EngineLock? = EngineLock("Test.diag.shared") + let second = EngineLock("Test.diag.shared") + first?.withLock {} + second.withLock {} + second.withLock {} + XCTAssertEqual(try XCTUnwrap(stats("Test.diag.shared")).instances, 2) + first = nil + let result = try XCTUnwrap(stats("Test.diag.shared")) + XCTAssertEqual(result.instances, 1) + XCTAssertEqual(result.acquisitions, 3) + } + + func test_diagnostics_recordSourceLocationsWhenAsked() throws { + let previous = EngineLockDiagnostics.recordsSites + EngineLockDiagnostics.recordsSites = true + defer { EngineLockDiagnostics.recordsSites = previous } + + let lock = EngineLock("Test.diag.sites") + for _ in 0 ..< 5 { + lock.lock() + lock.unlock() + } + let site = try XCTUnwrap(EngineLockDiagnostics.sites(top: 10000).first { $0.name == "Test.diag.sites" }) + XCTAssertEqual(site.count, 5) + XCTAssertTrue(site.file.hasSuffix("EngineLockTests.swift"), site.file) + XCTAssertGreaterThan(site.line, 0) + } + + func test_diagnostics_frameDeltaReportsOnlyWhatHappenedSinceThePreviousCall() throws { + let lock = EngineLock("Test.diag.delta") + lock.withLock {} + _ = EngineLockDiagnostics.consumeFrameDelta() + lock.withLock {} + lock.withLock {} + let delta = try XCTUnwrap(EngineLockDiagnostics.consumeFrameDelta().first { $0.name == "Test.diag.delta" }) + XCTAssertEqual(delta.acquisitions, 2) + XCTAssertNil(EngineLockDiagnostics.consumeFrameDelta().first { $0.name == "Test.diag.delta" }) + } + + func test_diagnostics_reportListsTheLockByName() { + let lock = EngineLock("Test.diag.report") + lock.withLock {} + XCTAssertTrue(EngineLockDiagnostics.report(top: 10000).contains("Test.diag.report")) + } + + #else + + func test_diagnostics_areAbsentFromANormalBuild() { + XCTAssertFalse(EngineLockDiagnostics.isCompiledIn) + let lock = EngineLock("Test.diag.absent") + lock.withLock {} + XCTAssertTrue(EngineLockDiagnostics.snapshot().isEmpty) + XCTAssertTrue(EngineLockDiagnostics.consumeFrameDelta().isEmpty) + XCTAssertTrue(EngineLockDiagnostics.sites().isEmpty) + } + + #endif + + // MARK: - Cost (opt-in, meaningful in a release build) + + /// Prints the cost of an uncontended lock and unlock for each engine lock type next to the + /// primitives they replace. Opt-in: `UNTOLD_LOCK_COST=1`, with a release build: + /// + /// UNTOLD_LOCK_COST=1 swift test -c release -Xswiftc -enable-testing --filter EngineLockTests/test_cost + /// + /// In a normal build `EngineLock` must cost what the bare `os_unfair_lock` costs. + func test_cost_uncontendedLockAndUnlock() throws { + guard ProcessInfo.processInfo.environment["UNTOLD_LOCK_COST"] == "1" else { + throw XCTSkip("Set UNTOLD_LOCK_COST=1 to run the lock cost comparison") + } + let operations = 5_000_000 + + func nanosecondsPerOperation(_ body: () -> Void) -> Double { + var best = Double.greatestFiniteMagnitude + for _ in 0 ..< 7 { + let start = DispatchTime.now().uptimeNanoseconds + body() + best = min(best, Double(DispatchTime.now().uptimeNanoseconds - start) / Double(operations)) + } + return best + } + + let counter = Counter() + + let raw = UnsafeMutablePointer.allocate(capacity: 1) + raw.initialize(to: os_unfair_lock()) + defer { + raw.deinitialize(count: 1) + raw.deallocate() + } + let rawNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + os_unfair_lock_lock(raw) + counter.value &+= 1 + os_unfair_lock_unlock(raw) + } + } + + let allocated = OSAllocatedUnfairLock() + let allocatedNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + allocated.lock() + counter.value &+= 1 + allocated.unlock() + } + } + + let engineLock = EngineLock("Test.cost.lock") + let engineNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + engineLock.lock() + counter.value &+= 1 + engineLock.unlock() + } + } + + let protected = EngineProtected("Test.cost.protected", 0) + let protectedNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + protected.withLock { $0 &+= 1 } + } + } + + let nsLock = NSLock() + let nsLockNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + nsLock.lock() + counter.value &+= 1 + nsLock.unlock() + } + } + + let engineRecursive = EngineRecursiveLock("Test.cost.recursive") + let engineRecursiveNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + engineRecursive.lock() + counter.value &+= 1 + engineRecursive.unlock() + } + } + + let nsRecursive = NSRecursiveLock() + let nsRecursiveNs = nanosecondsPerOperation { + for _ in 0 ..< operations { + nsRecursive.lock() + counter.value &+= 1 + nsRecursive.unlock() + } + } + + print(String(format: "LOCK_COST diagnostics=%@", EngineLockDiagnostics.isCompiledIn ? "on" : "off")) + print(String(format: "LOCK_COST os_unfair_lock %6.2f ns", rawNs)) + print(String(format: "LOCK_COST OSAllocatedUnfairLock %6.2f ns", allocatedNs)) + print(String(format: "LOCK_COST EngineLock %6.2f ns", engineNs)) + print(String(format: "LOCK_COST EngineProtected %6.2f ns", protectedNs)) + print(String(format: "LOCK_COST NSLock %6.2f ns", nsLockNs)) + print(String(format: "LOCK_COST EngineRecursiveLock %6.2f ns", engineRecursiveNs)) + print(String(format: "LOCK_COST NSRecursiveLock %6.2f ns", nsRecursiveNs)) + XCTAssertGreaterThan(counter.value, 0) + } +} diff --git a/docs/API/UsingProfiler.md b/docs/API/UsingProfiler.md index 1defe3d7e..7b7eac96c 100644 --- a/docs/API/UsingProfiler.md +++ b/docs/API/UsingProfiler.md @@ -227,6 +227,61 @@ GPU passes (9, sum 6.21ms): Forward 3.10 | Shadows 0.62 | SSAO 0.55 | Post 0.40 Results come from the command buffer's completion handler, so the snapshot describes the most recently *completed* frame. +## Lock Diagnostics + +Every engine lock is an `EngineLock`, an `EngineProtected` or an `EngineRecursiveLock` (`Utils/EngineLock.swift`), each created with a name. In a normal build they compile down to the bare `os_unfair_lock` call: an uncontended lock and unlock costs the same as the primitive (1.7 ns on an M4 Max, against 5.9 ns for `NSLock` and 11.3 ns for `NSRecursiveLock`; `EngineRecursiveLock` costs 2.9 ns). + +Built with the compile-time flag `ENGINE_LOCK_DIAGNOSTICS`, the same types also count every acquisition and time how long each lock was waited for and held. It is a build mode and not a runtime switch on purpose: a frame takes hundreds of thousands of locks, and a runtime check on each would cost a measurable part of the frame it is measuring. + +```bash +swift build -Xswiftc -DENGINE_LOCK_DIAGNOSTICS # SwiftPM +xcodebuild ... 'SWIFT_ACTIVE_COMPILATION_CONDITIONS=$(inherited) ENGINE_LOCK_DIAGNOSTICS' +scripts/perf/run_bench.sh macos --lock-diagnostics # PerfBench, own build folder +``` + +In such a build the verbose stats output adds one line with the busiest locks of the frame, and `EngineStatsSnapshot.locks` carries the per-frame numbers for every lock name (the recorder's summary keeps `lockCallsPerFrame`, `lockHoldMsPerFrame`, `lockContended` and `lockWaitMs`): + +``` +Locks: 125663 calls | contended 0 | wait 0.00ms | held 6.93ms | Globals.core 65814 | ECS.componentIds 48599 | Scene.channelRenderMode 10398 | Globals.runtime 851 +``` + +For a table over any period, reset the counters, run the work and print the report: + +```swift +EngineLockDiagnostics.reset() +for _ in 0 ..< 120 { renderer.draw(in: view) } +print(EngineLockDiagnostics.report(per: 120, unit: "frame")) +``` + +``` +Engine locks: 125663.1 lock calls per frame + lock taken reentries contended wait ms hold ms max hold ms instances + Globals.core 55746.6 10068.0 0 0.000 4.269 7.7047 1 + ECS.componentIds 48599.4 0.0 0 0.000 1.863 1.1247 1 + Scene.channelRenderMode 10398.0 0.0 0 0.000 0.760 5.2308 1 + Globals.runtime 851.1 0.0 5 0.004 0.034 0.2187 1 + by source location (calls per frame) + 62973.4 UntoldEngine/Globals.swift:90 [Globals.core] + 48599.4 UntoldEngine/ComponentPool.swift:40 [ECS.componentIds] + 10398.0 UntoldEngine/SceneContextVisibility.swift:85 [Scene.channelRenderMode] +``` + +| Column | What it tells you | +|---|---| +| `taken` | Times the lock was taken, per frame (or per whatever `per:` divides by). Locks created with the same name are reported together. | +| `reentries` | Times a thread that already held a recursive lock took it again. A lock call all the same, and a sign that a caller holds the lock across code that reads the same state. | +| `contended` | Acquisitions that found the lock held by another thread and had to wait. Zero on a single-threaded path means the lock protects nothing there: the question is why it is taken at all. | +| `wait ms` | Total time spent waiting in contended acquisitions. This is the cost of contention. | +| `hold ms` | Time the lock was held, per frame. The clock ticks every 42 ns on Apple silicon and the instrumentation itself runs inside the hold, so read it summed over many acquisitions and compare it between runs of the same build mode; it is not an absolute cost. | +| `max hold ms` | Longest single hold since the last reset. A lock held for milliseconds will stall any other thread that needs it, however rarely that happens. | +| `instances` | Live lock objects under this name. | + +The source-location rows appear when `EngineLockDiagnostics.recordsSites` is on (`UNTOLD_LOCK_SITES=1` in the environment). They name the file and line of the `lock()` or `withLock` call, which for a global accessor is the accessor: enough to tell which global is read per entity. + +Frame times from a diagnostics build are not comparable with a normal build: at 1,000 cubes the instrumentation adds several milliseconds. Judge it on counts, contention and wait time, and take frame times from a normal build. `EngineLockDiagnostics.isCompiledIn` tells the two apart at runtime, and PerfBench records it as `render.lockDiagnostics` so the comparer never matches such a run to a normal baseline. + +Locks still declared as `NSLock` or `NSRecursiveLock` are invisible to these counters; the opt-in `LockCensusTests` (`UNTOLD_LOCK_CENSUS=1`) counts those through a hook and prints both views. + ## OOC And Asset Triage Mode High-volume instrumentation categories are disabled by default: From ae32c2660fef91fd7cf9daa1649ef9b047f7309f Mon Sep 17 00:00:00 2001 From: Javier Segura Date: Sat, 3 Oct 2026 19:40:29 +0200 Subject: [PATCH 2/4] [Performance] Move the frame's four busiest locks to the engine lock types The four locks that make up 98 % of the frame's lock calls (docs/proposals/ActorsAndLocks.md, section 6, items 1, 2, 3 and 5) now use the engine lock types, under these names: - Globals.core: CoreRuntimeGlobals (scene, renderInfo, the pipelines), an EngineRecursiveLock in place of an NSRecursiveLock. Recursive on purpose: a _modify accessor holds it across the caller's mutation. - Globals.runtime: RuntimeGlobalsStore, likewise. - ECS.componentIds: the component type to id map, an EngineProtected in place of a bare OSAllocatedUnfairLock. - Scene.channelRenderMode: SceneChannelVisibilityState, an EngineLock in place of an NSLock. A diagnostics build now sees them. renderer.draw at 1,000 cubes: 125,663 lock calls per frame (Globals.core 55,747 taken and 10,068 re-entered, component ids 48,599, channel render mode 10,398, Globals.runtime 851), none contended on the frame path, against 3,273 calls left on NSLock. LockCensusTests prints this report next to its NSLock census when built with ENGINE_LOCK_DIAGNOSTICS. Frame time in a normal release build (renderer.draw wall time in the census harness, before and after interleaved on an idle machine): 1,000 cubes 6.51 / 6.55 / 6.73 ms -> 6.39 / 6.41 / 6.50 ms 4,000 cubes 26.39 .. 31.96 ms (5 runs, median 27.20) -> 25.49 .. 27.10 ms (7 runs, median 25.78) About 2 % and 3 to 5 %: the calls are cheaper, there are as many as before. Verified: core suite (1523 tests; the one failure is the known checkout-folder name dependency of ExternalRenderExtensionPackageTests), the async mesh loading and loading gate render tests (31), EngineLockTests under Thread Sanitizer, the strict-concurrency guardrail, PerfBench macOS and visionOS simulator builds. --- Sources/UntoldEngine/ECS/ComponentPool.swift | 5 +- Sources/UntoldEngine/Utils/Globals.swift | 6 +- .../Utils/SceneContextVisibility.swift | 2 +- .../LockCensusTests.swift | 34 +++++++++ docs/proposals/ActorsAndLocks.md | 70 +++++++++++++++++-- 5 files changed, 107 insertions(+), 10 deletions(-) diff --git a/Sources/UntoldEngine/ECS/ComponentPool.swift b/Sources/UntoldEngine/ECS/ComponentPool.swift index 117908aee..447da0ed6 100644 --- a/Sources/UntoldEngine/ECS/ComponentPool.swift +++ b/Sources/UntoldEngine/ECS/ComponentPool.swift @@ -10,7 +10,6 @@ // file, You can obtain one at https://mozilla.org/MPL/2.0/. import Foundation -import os struct TypeInfo { var id: Int @@ -28,8 +27,8 @@ public struct ComponentTypeRegistration: Equatable, Sendable { } /// Component type → id map. Read on every component access and written only when a new type -/// registers, so it sits behind an unfair lock rather than an NSLock. -private let componentIDState = OSAllocatedUnfairLock<[ObjectIdentifier: TypeInfo]>(initialState: [:]) +/// registers. +private let componentIDState = EngineProtected<[ObjectIdentifier: TypeInfo]>("ECS.componentIds", [:]) @inline(__always) func componentTypeInfosSnapshot() -> [ObjectIdentifier: TypeInfo] { diff --git a/Sources/UntoldEngine/Utils/Globals.swift b/Sources/UntoldEngine/Utils/Globals.swift index d2652de44..855da5f7f 100644 --- a/Sources/UntoldEngine/Utils/Globals.swift +++ b/Sources/UntoldEngine/Utils/Globals.swift @@ -36,7 +36,9 @@ let maxAreaLights: Int = 100 private final class CoreRuntimeGlobals: @unchecked Sendable { static let shared = CoreRuntimeGlobals() - let lock = NSRecursiveLock() + /// Recursive on purpose: a `_modify` accessor holds it across the caller's mutation, which + /// reads other globals of this store. + let lock = EngineRecursiveLock("Globals.core") var scene = Scene() var shadowSystem: ShadowSystem! var pointShadowState: PointShadowState! @@ -1098,7 +1100,7 @@ var environmentMesh: MTKMesh! { private final class RuntimeGlobalsStore: @unchecked Sendable { static let shared = RuntimeGlobalsStore() - private let lock = NSRecursiveLock() + private let lock = EngineRecursiveLock("Globals.runtime") private var componentCounterValue: Int = 0 private var globalEntityCounterValue: UInt32 = 0 private var timeSinceLastUpdatePreviousTimeValue: TimeInterval? diff --git a/Sources/UntoldEngine/Utils/SceneContextVisibility.swift b/Sources/UntoldEngine/Utils/SceneContextVisibility.swift index 51d7a94e5..caba4a593 100644 --- a/Sources/UntoldEngine/Utils/SceneContextVisibility.swift +++ b/Sources/UntoldEngine/Utils/SceneContextVisibility.swift @@ -58,7 +58,7 @@ public enum SceneChannelProperty: Sendable { private final class SceneChannelVisibilityState: @unchecked Sendable { static let shared = SceneChannelVisibilityState() - private let lock = NSLock() + private let lock = EngineLock("Scene.channelRenderMode") private var renderModesByChannelRawValue: [UInt64: SceneChannelRenderMode] = [:] func setVisible(_ channel: SceneChannel, visible: Bool) { diff --git a/Tests/UntoldEngineRenderTests/LockCensusTests.swift b/Tests/UntoldEngineRenderTests/LockCensusTests.swift index a6d97904f..b86b07dec 100644 --- a/Tests/UntoldEngineRenderTests/LockCensusTests.swift +++ b/Tests/UntoldEngineRenderTests/LockCensusTests.swift @@ -17,6 +17,10 @@ import XCTest /// Counts every `NSLock` / `NSRecursiveLock` acquisition made while a frame runs and /// attributes it to the engine function that took the lock. /// +/// Locks already moved to the engine's own lock types (`EngineLock`, `EngineProtected`, +/// `EngineRecursiveLock`) are invisible to this hook; build with `-Xswiftc -DENGINE_LOCK_DIAGNOSTICS` +/// and the test also prints their counts and timings from `EngineLockDiagnostics`. +/// /// Opt-in: runs only with `UNTOLD_LOCK_CENSUS=1`. Pipe the output through /// `xcrun swift-demangle` to read the function names. /// @@ -186,6 +190,36 @@ final class LockCensusTests: BaseRenderSetup { } let plainMs = Double(DispatchTime.now().uptimeNanoseconds - start) / 1e6 / Double(frames) + // The engine's own lock types are not NSLocks, so the hook below does not see them. A + // build with ENGINE_LOCK_DIAGNOSTICS counts them itself; UNTOLD_LOCK_SITES=1 adds the + // source location of every call. + if EngineLockDiagnostics.isCompiledIn { + EngineLockDiagnostics.reset() + for _ in 0 ..< frames { + renderer.draw(in: renderer.metalView) + } + print("=== ENGINE LOCKS: renderer.draw, \(entityCount) cubes + test scene") + print(EngineLockDiagnostics.report(per: frames, unit: "frame", top: 40)) + + EngineLockDiagnostics.reset() + for (i, entity) in entities.enumerated() { + translateTo(entityId: entity, position: simd_float3(Float(i % side) * 0.4, Float(i / side) * 0.4, -20.5)) + } + print("=== ENGINE LOCKS: translateTo(entityId:position:)") + print(EngineLockDiagnostics.report(per: entities.count, unit: "call", top: 12)) + + EngineLockDiagnostics.reset() + var checksum: Float = 0 + for entity in entities { + if let transform = scene.get(component: LocalTransformComponent.self, for: entity) { + checksum += transform.position.x + } + } + XCTAssertFalse(checksum.isNaN) + print("=== ENGINE LOCKS: scene.get(component:for:)") + print(EngineLockDiagnostics.report(per: entities.count, unit: "call", top: 12)) + } + LockCensus.install() // 0. Self-check. A lock taken a known number of times from a known function must come back diff --git a/docs/proposals/ActorsAndLocks.md b/docs/proposals/ActorsAndLocks.md index 7fbe47ae4..f2088a518 100644 --- a/docs/proposals/ActorsAndLocks.md +++ b/docs/proposals/ActorsAndLocks.md @@ -1,6 +1,6 @@ # Actors and Locks in the Engine — Benchmark, Lock Census and Rules (Research) -Status: research with measurements, no engine change. Measured 2026-10-03 on `develop` (`108169ce`), Mac16,5 (M4 Max, 12 performance + 4 efficiency cores), macOS 27.0, Xcode 27.0 / Swift 6.4, release builds. Nothing here was measured on a Vision Pro or an iPhone. +Status: research with measurements; the review of section 6 has started on the fork branch `feature/perf_locks` (section 9). The research itself was measured 2026-10-03 on `develop` (`108169ce`), Mac16,5 (M4 Max, 12 performance + 4 efficiency cores), macOS 27.0, Xcode 27.0 / Swift 6.4, release builds. Nothing here was measured on a Vision Pro or an iPhone. Two questions: @@ -24,8 +24,8 @@ Everything below can be re-run with the commands in section 7: the benchmark is - No actor may own state that the update, render or XR thread reads or writes. - An actor is allowed when every caller is already `async` and the calls are per asset or per request, never per entity or per frame. - When the frame needs to see state owned by an actor, the actor publishes it through a lock-protected snapshot. `AssetLoadingState` (actor) with `AssetLoadingGate` (lock) is the existing example. -- Default lock: `OSAllocatedUnfairLock` (macOS 13, iOS 16, visionOS 1). `Synchronization.Mutex` is as fast but needs macOS 15 and iOS 18, above the engine's minimums (macOS 14, iOS 17, visionOS 2). -- `NSRecursiveLock` only where re-entry is real, and never on a per-entity path. +- Default lock: `EngineLock`, or `EngineProtected` when the lock owns the state (`Utils/EngineLock.swift`). Both are an `os_unfair_lock` and compile down to the bare call; built with `ENGINE_LOCK_DIAGNOSTICS` they count and time themselves (section 9). `Synchronization.Mutex` is as fast but needs macOS 15 and iOS 18, above the engine's minimums (macOS 14, iOS 17, visionOS 2). +- `EngineRecursiveLock` only where re-entry is real, and never on a per-entity path. No new `NSLock`, `NSRecursiveLock` or bare `OSAllocatedUnfairLock`: a lock outside the engine types cannot be measured with the others. - A serial or concurrent `DispatchQueue` is not a lock: `queue.sync` costs 170 ns uncontended, 50 times an unfair lock. - Per-frame code reads shared state once per system or pass, not once per entity. @@ -170,11 +170,73 @@ swift run -c release --package-path Examples/ConcurrencyBench ConcurrencyBench 4 # Lock census of the frame (opt-in test, skipped otherwise) UNTOLD_LOCK_CENSUS=1 UNTOLD_LOCK_CENSUS_ENTITIES=4000 UNTOLD_LOCK_CENSUS_FRAMES=120 CI=true \ swift test -c release -Xswiftc -enable-testing --filter LockCensusTests 2>&1 | xcrun swift-demangle --simplified + +# Counts, contention, wait and hold time of the engine lock types (diagnostics build mode) +UNTOLD_LOCK_CENSUS=1 UNTOLD_LOCK_SITES=1 UNTOLD_LOCK_CENSUS_ENTITIES=1000 UNTOLD_LOCK_CENSUS_FRAMES=120 \ + swift test -c release -Xswiftc -enable-testing -Xswiftc -DENGINE_LOCK_DIAGNOSTICS --filter LockCensusTests +scripts/perf/run_bench.sh macos --lock-diagnostics # the same numbers per PerfBench scene + +# Cost of the lock types against the primitives they replace +UNTOLD_LOCK_COST=1 swift test -c release -Xswiftc -enable-testing --filter EngineLockTests/test_cost ``` ## 8. Limits - One machine, macOS only. The ratios should hold on iOS and visionOS (same runtime, same lock implementations); the absolute numbers will not. The pool-saturation result depends on core count: fewer cores saturate sooner. - The census scene is static cubes plus the render-test scene: no animation, physics, streaming load or XR. Those paths are reviewed from the source only. -- The census counts `NSLock` and `NSRecursiveLock`. It does not count `OSAllocatedUnfairLock` (3 sites) or dispatch queues. +- The census counts `NSLock` and `NSRecursiveLock`. It does not count `OSAllocatedUnfairLock` (3 sites), dispatch queues or the engine lock types; the last are counted by the diagnostics build mode instead (section 9). - The frame times are the wall time of `renderer.draw` in a headless test, which includes command encoding but not presentation. + +## 9. Status of the review (fork branch `feature/perf_locks`, 2026-10-03) + +**The lock types.** `EngineLock`, `EngineProtected` and `EngineRecursiveLock` (`Utils/EngineLock.swift`) are the engine's locks from here on. Uncontended lock and unlock, release build, M4 Max: + +| | ns | +|---|---| +| `os_unfair_lock` (the primitive) | 1.73 | +| `EngineLock` | 1.74 | +| `EngineProtected` | 1.75 | +| `EngineRecursiveLock` | 2.91 | +| `NSLock` | 5.88 | +| `NSRecursiveLock` | 11.25 | + +The recursive lock keeps an owner word next to an unfair lock. A thread reads it without the lock to recognise its own re-entry, through C11 atomics (`Sources/CEngineAtomics`), so it is clean under Thread Sanitizer. + +**Diagnostics are a build mode.** Compiled with `ENGINE_LOCK_DIAGNOSTICS`, the same types count acquisitions and re-entries, detect contention with a trylock, and time the wait and the hold, per named lock and optionally per source location. The numbers land in `EngineStatsSnapshot.locks`, so PerfBench reports them per scene (`run_bench.sh --lock-diagnostics`). A normal build carries none of it. A runtime switch was rejected: at half a million lock calls per frame, a one-nanosecond check is half a millisecond. + +**Moved so far**: the four locks of items 1, 2, 3 and 5. + +| Lock name | What | Was | +|---|---|---| +| `Globals.core` | `CoreRuntimeGlobals` (`scene`, `renderInfo`, the pipelines) | `NSRecursiveLock` | +| `Globals.runtime` | `RuntimeGlobalsStore` (the scalar globals) | `NSRecursiveLock` | +| `ECS.componentIds` | component type to id map | `OSAllocatedUnfairLock` since batch one, `NSLock` before | +| `Scene.channelRenderMode` | `SceneChannelVisibilityState` | `NSLock` | + +What the diagnostics build reports for `renderer.draw` at 1,000 cubes (120 frames): + +| Lock | Taken per frame | Re-entries per frame | Contended | Top source location | +|---|---|---|---|---| +| `Globals.core` | 55,747 | 10,068 | 0 | `scene` getter 62,973; `renderInfo` getter 2,636 | +| `ECS.componentIds` | 48,599 | 0 | 0 | `componentTypeInfo(for:)` | +| `Scene.channelRenderMode` | 10,398 | 0 | 0 | `renderMode(for:)` | +| `Globals.runtime` | 851 | 0 | 5 | `pomQualitySettings` getter 730 | + +That is 125,663 lock calls per frame, against 3,273 left on `NSLock` (per-entity reads of per-frame constants in the model pass and `opaqueLODDraws`, item 4). `translateTo(entityId:position:)` takes 20 lock calls and `scene.get(component:for:)` takes 2. A PerfBench run of `primitives-1k` reports 169,612 lock calls per frame, none contended. + +Three things the counts show that the census could not: + +- `Globals.runtime` is never re-entered in the frame, which supports item 5 (it does not need to be recursive). To confirm on the loading and editor paths before changing it. +- `Globals.core` is re-entered 10,000 times per frame: a `_modify` on one global holds the lock while its body reads `scene`. Those are the callers the scene borrow has to restructure. +- Nothing on the frame path is contended. Every one of these calls protects against a thread that is not there. + +**Frame time, normal release build**, `renderer.draw` wall time in the census harness, before (batch one, component ids already behind an unfair lock) and after, runs interleaved on an idle machine: + +| Scene | Before (ms) | After (ms) | Best against best | +|---|---|---|---| +| 1,000 cubes | 6.51 / 6.55 / 6.73 | 6.39 / 6.41 / 6.50 | 1.8 % | +| 4,000 cubes | 26.39 / 26.75 / 27.20 / 27.41 / 31.96 | 25.49 / 25.62 / 25.64 / 25.78 / 25.88 / 26.27 / 27.10 | 3.4 % | + +A small gain, as section 5 predicted for a better primitive: the calls are cheaper, there are just as many. The large one is still to remove them. + +**Next, in this order** (each with its own before and after): component ids without a lock (a per-type static id; the current check-then-register is also not atomic across threads); a lock-free fast path for the scene-channel check when no channel is overridden; per-frame constants read once per pass (the 3,273 remaining `NSLock` calls); `Globals.runtime` as a plain lock; then the scene borrow, which needs a design. The remaining 100 or so `NSLock` declarations move to the engine types in slices, hot paths first. Once they have, `LockCensusTests` is redundant. From 1ba8b091be81ff8750bc8bb457dd6868bc5d1e9c Mon Sep 17 00:00:00 2001 From: Javier Segura Date: Sat, 3 Oct 2026 19:40:29 +0200 Subject: [PATCH 3/4] [Feature] PerfBench: lock diagnostics build mode run_bench.sh --lock-diagnostics builds the engine with ENGINE_LOCK_DIAGNOSTICS (into its own build folder, so switching modes does not rebuild the engine) and each scene then reports lock calls per frame, contention and wait time; the per-lock numbers are in the scene summaries and in every recorded frame. Frame times of such a build are not comparable with a normal one, so the run records render.lockDiagnostics, the comparer keys baselines on it and the script skips the baseline comparison in this mode. First run (Mac16,5, 60 Hz): cube 942 lock calls per frame, primitives-1k 169,612, none contended. --- Examples/PerfBench/README.md | 1 + .../Sources/PerfBenchCore/BenchResults.swift | 14 ++++++++++++-- .../Sources/PerfBenchCore/BenchRunner.swift | 1 + scripts/perf/compare_baseline.py | 3 +++ scripts/perf/run_bench.sh | 14 ++++++++++++++ 5 files changed, 31 insertions(+), 2 deletions(-) diff --git a/Examples/PerfBench/README.md b/Examples/PerfBench/README.md index 0e50f9e82..3a8d998bb 100644 --- a/Examples/PerfBench/README.md +++ b/Examples/PerfBench/README.md @@ -57,6 +57,7 @@ scripts/perf/run_bench.sh ios --device 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 --xctrace "Metal System Trace" +scripts/perf/run_bench.sh macos --lock-diagnostics # count and time every engine lock ``` Runs land in `perf/results/-/` with `.jsonl`, `summary.json` and the diff --git a/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift b/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift index 17681026a..21ae74ef4 100644 --- a/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift +++ b/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 @@ -125,10 +128,17 @@ 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, +) + ) 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 )) } return lines.joined(separator: "\n") diff --git a/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift b/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift index b90c20243..d7b4cdc92 100644 --- a/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift +++ b/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift @@ -108,6 +108,7 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable { } } render.antiAliasing = String(describing: antiAliasingMode) + render.lockDiagnostics = EngineLockDiagnostics.isCompiledIn summary.render = render gameMode = true setState(.building(0)) diff --git a/scripts/perf/compare_baseline.py b/scripts/perf/compare_baseline.py index 462a91f55..be35ac8b4 100755 --- a/scripts/perf/compare_baseline.py +++ b/scripts/perf/compare_baseline.py @@ -63,6 +63,9 @@ def rate(numerator, denominator): # Frames are display-paced, and the GPU stretches its work over the slack a slower display # leaves, so times taken at different refresh rates are not comparable. ("displayRefreshHz", 0.0), + # A build with ENGINE_LOCK_DIAGNOSTICS counts and times every engine lock, so its frame and + # CPU times are not comparable with a normal build's. + ("lockDiagnostics", False), ] diff --git a/scripts/perf/run_bench.sh b/scripts/perf/run_bench.sh index 1d2f5e480..7f53d632e 100755 --- a/scripts/perf/run_bench.sh +++ b/scripts/perf/run_bench.sh @@ -19,6 +19,10 @@ # --refresh N macOS: run on a connected display whose maximum refresh rate is N Hz # (default: the fastest connected display). Baselines are keyed by the rate. # --xctrace TEMPLATE also record an Instruments trace, e.g. "Metal System Trace" (device runs) +# --lock-diagnostics build the engine with ENGINE_LOCK_DIAGNOSTICS: every engine lock is counted +# and timed, and each scene reports lock calls, contention, wait and hold +# time. Frame times of such a build are not comparable with a normal one, +# so the baseline comparison is skipped. # --no-compare skip the baseline comparison # --update-baseline write this run as the new baseline for the device model # @@ -42,6 +46,7 @@ LABEL="$(git -C "$REPO" describe --always --dirty 2>/dev/null || echo unknown)" CONFIG=Release DEVICE="" XCTRACE_TEMPLATE="" +LOCK_DIAGNOSTICS=0 COMPARE=1 UPDATE_BASELINE=0 REPEAT=1 @@ -59,6 +64,7 @@ while [ $# -gt 0 ]; do --repeat) REPEAT="$2"; shift 2 ;; --refresh) REFRESH="$2"; shift 2 ;; --xctrace) XCTRACE_TEMPLATE="$2"; shift 2 ;; + --lock-diagnostics) LOCK_DIAGNOSTICS=1; COMPARE=0; shift ;; --no-compare) COMPARE=0; shift ;; --update-baseline) UPDATE_BASELINE=1; shift ;; *) echo "unknown option $1"; exit 2 ;; @@ -67,6 +73,13 @@ done RUN_ID="$(date +%Y%m%d-%H%M%S)-$PLATFORM" DERIVED="$BENCH_DIR/.build/DerivedData" +EXTRA_BUILD_SETTINGS=() +if [ "$LOCK_DIAGNOSTICS" -eq 1 ]; then + # A separate build folder, so switching modes does not rebuild the engine each time. A build + # setting given on the command line reaches the engine package's targets as well. + DERIVED="$BENCH_DIR/.build/DerivedData-lockdiag" + EXTRA_BUILD_SETTINGS+=('SWIFT_ACTIVE_COMPILATION_CONDITIONS=$(inherited) ENGINE_LOCK_DIAGNOSTICS') +fi mkdir -p "$OUT_DIR" case "$PLATFORM" in @@ -88,6 +101,7 @@ xcodebuild build \ -derivedDataPath "$DERIVED" \ -allowProvisioningUpdates \ ARCHS=arm64 ONLY_ACTIVE_ARCH=YES \ + ${EXTRA_BUILD_SETTINGS[@]+"${EXTRA_BUILD_SETTINGS[@]}"} \ -quiet SUMMARIES=() From 75ffc4b1de4bf34028d1d3d0b9dc289b787af42b Mon Sep 17 00:00:00 2001 From: Javier Segura Date: Sat, 3 Oct 2026 20:54:18 +0200 Subject: [PATCH 4/4] [Feature] PerfBench: lock scenes, sessions and a gate that knows when the machine is busy Lock scenes (the 1k grid plus one kind of work against shared state): - locks-api: game code reads and moves every entity through the public API each frame. - locks-loading: an asset loads, is destroyed and loads again while the frame renders. - locks-threads: a second thread reads every entity's transform in a loop, as a render thread reads what the main thread updates on visionOS. Scenes get a per-frame update hook, and the runner waits for a scene to become quiescent (a load in flight, a reader thread) before destroying its entities. Sessions in run_bench.sh: - quick: cube, primitives-1k, animation-16, stadium, 10 s, three repeats. The gate for every change, about three minutes. - locks: a build with ENGINE_LOCK_DIAGNOSTICS on primitives-1k and the three lock scenes, judged on lock calls and lock wait time per frame, per lock name, against a lock baseline of its own (perf/baselines//-lockdiag). - full: every scene with three repeats, then the locks session. Lock baseline for Mac16,5 (diagnostics build, two runs): primitives-1k 167,262 lock calls per frame, locks-api 213,590, locks-loading 166,988, locks-threads 178,954 with Globals.core contended about 2,600 times and 0.9 ms of waiting per frame. Lock calls repeat to within 0.02 % between runs. Normal-build baselines for the three lock scenes are added as well. The gate on a Mac that is not idle. Other processes (photo and media analysis daemons, here) used three to six cores during a quick session; in that state light scenes skip refreshes in bursts and their sub-millisecond CPU times read two to four times higher, in the baseline branch as well. So: - each scene records how many cores other processes used while it was recorded and the fraction of frames the app was frontmost; the console line says MACHINE BUSY from one core up; - when even the quietest repeat was that busy, the comparer reports the scene's frame pacing as information and says so at the end; - a per-system CPU mean is judged only when the baseline's value is at least 1 ms. First quick session on this branch against the 120 Hz baseline: no regressions, primitives-1k encode 5.33 ms against 6.32 ms (-15.7 %), the light scenes within 1 % of the baseline in their best run. --- Examples/PerfBench/README.md | 31 +- .../Sources/PerfBenchCore/BenchResults.swift | 69 ++- .../Sources/PerfBenchCore/BenchRunner.swift | 50 +- .../Sources/PerfBenchCore/BenchScenes.swift | 16 +- .../Sources/PerfBenchCore/LockScenes.swift | 230 ++++++++ .../PerfBench/Sources/macOS/AppDelegate.swift | 1 + .../Mac16_5/macOS-lockdiag/locks-api.json | 514 ++++++++++++++++++ .../Mac16_5/macOS-lockdiag/locks-loading.json | 514 ++++++++++++++++++ .../Mac16_5/macOS-lockdiag/locks-threads.json | 514 ++++++++++++++++++ .../Mac16_5/macOS-lockdiag/primitives-1k.json | 514 ++++++++++++++++++ perf/baselines/Mac16_5/macOS/locks-api.json | 428 +++++++++++++++ .../Mac16_5/macOS/locks-loading.json | 428 +++++++++++++++ .../Mac16_5/macOS/locks-threads.json | 428 +++++++++++++++ scripts/perf/compare_baseline.py | 122 ++++- scripts/perf/run_bench.sh | 58 +- 15 files changed, 3890 insertions(+), 27 deletions(-) create mode 100644 Examples/PerfBench/Sources/PerfBenchCore/LockScenes.swift create mode 100644 perf/baselines/Mac16_5/macOS-lockdiag/locks-api.json create mode 100644 perf/baselines/Mac16_5/macOS-lockdiag/locks-loading.json create mode 100644 perf/baselines/Mac16_5/macOS-lockdiag/locks-threads.json create mode 100644 perf/baselines/Mac16_5/macOS-lockdiag/primitives-1k.json create mode 100644 perf/baselines/Mac16_5/macOS/locks-api.json create mode 100644 perf/baselines/Mac16_5/macOS/locks-loading.json create mode 100644 perf/baselines/Mac16_5/macOS/locks-threads.json diff --git a/Examples/PerfBench/README.md b/Examples/PerfBench/README.md index 3a8d998bb..89974e971 100644 --- a/Examples/PerfBench/README.md +++ b/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,7 +56,11 @@ 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 @@ -60,6 +70,14 @@ scripts/perf/run_bench.sh visionos --device --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//-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/-/` with `.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 @@ -79,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: diff --git a/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift b/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift index 21ae74ef4..ef442f2fc 100644 --- a/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift +++ b/Examples/PerfBench/Sources/PerfBenchCore/BenchResults.swift @@ -88,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.stride / MemoryLayout.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 { @@ -135,10 +194,16 @@ public struct BenchRunSummary: Codable, Sendable { 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, locks + s.framesOverBudget, s.meanGPUExecutionMs, miss, s.worstThermalState, locks, inactive )) } return lines.joined(separator: "\n") diff --git a/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift b/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift index d7b4cdc92..ab4e8f853 100644 --- a/Examples/PerfBench/Sources/PerfBenchCore/BenchRunner.swift +++ b/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 @@ -115,7 +124,7 @@ public final class BenchRunner: ObservableObject, @unchecked Sendable { } /// 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 { @@ -136,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() @@ -146,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)) } @@ -199,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 @@ -217,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) diff --git a/Examples/PerfBench/Sources/PerfBenchCore/BenchScenes.swift b/Examples/PerfBench/Sources/PerfBenchCore/BenchScenes.swift index 51c217e2b..df8abbe23 100644 --- a/Examples/PerfBench/Sources/PerfBenchCore/BenchScenes.swift +++ b/Examples/PerfBench/Sources/PerfBenchCore/BenchScenes.swift @@ -36,7 +36,8 @@ 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 } @@ -44,10 +45,20 @@ public protocol BenchScene { /// 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] { diff --git a/Examples/PerfBench/Sources/PerfBenchCore/LockScenes.swift b/Examples/PerfBench/Sources/PerfBenchCore/LockScenes.swift new file mode 100644 index 000000000..256580c9e --- /dev/null +++ b/Examples/PerfBench/Sources/PerfBenchCore/LockScenes.swift @@ -0,0 +1,230 @@ +// +// LockScenes.swift +// PerfBench +// +// Copyright (C) Untold Engine Studios +// +// This Source Code Form is subject to the terms of the Mozilla Public +// License, v. 2.0. If a copy of the MPL was not distributed with this +// file, You can obtain one at https://mozilla.org/MPL/2.0/. + +import Foundation +import simd +import SwiftUI +import UntoldEngine + +// Scenes of the `locks` session. Each one renders the same 1,024 primitives as `primitives-1k` +// and adds one kind of work against the engine's shared state: game code calling the public API +// for every entity, an asset loading while the frame renders, or a second thread reading the +// scene. In a build with ENGINE_LOCK_DIAGNOSTICS they are judged on lock calls per frame, +// contention, wait and hold time; in a normal build on frame and CPU times like any other scene. + +private enum LockSceneLayout { + static let gridSize = 32 + static let spacing: Float = 1.0 + static let orbit = BenchCameraOrbit(center: .zero, radius: 26.0, height: 12.0, period: 16.0) + + static func buildBase(origin: simd_float3, namePrefix: String) -> [EntityID] { + BenchSceneBuilder.makeCamera(eye: origin + orbit.eye(at: 0), target: origin) + BenchSceneBuilder.makeSun() + return BenchSceneBuilder.makeGrid( + origin: origin, + gridSize: gridSize, + spacing: spacing, + batched: false, + namePrefix: namePrefix + ) + } +} + +/// Game code that reads and moves every entity through the public API, every frame. +final class LockAPICallsScene: BenchScene { + let id = "locks-api" + let title = "1024 primitives moved through the public API every frame" + let notes = "getLocalPosition, translateTo and rotateBy on each entity per frame; measures what the public API costs in lock calls." + let orbit = LockSceneLayout.orbit + + private var entities: [EntityID] = [] + private var basePositions: [simd_float3] = [] + + func build(origin: simd_float3) { + entities = LockSceneLayout.buildBase(origin: origin, namePrefix: id) + basePositions = entities.map { getLocalPosition(entityId: $0) } + } + + func update(deltaTime: Float, elapsed: Double) { + let time = Float(elapsed) + for (index, entity) in entities.enumerated() { + let base = basePositions[index] + // A read, as game logic would do before deciding where the entity goes. + let current = getLocalPosition(entityId: entity) + let lift = 0.25 * sin(time * 2.0 + Float(index) * 0.21) + translateTo(entityId: entity, position: simd_float3(current.x, base.y + lift, current.z)) + rotateBy(entityId: entity, angle: 45.0 * deltaTime, axis: simd_float3(0, 1, 0)) + } + } + + func teardown() { + entities = [] + basePositions = [] + } +} + +/// An asset that keeps loading on the loader's threads while the frame renders. +final class LockLoadingScene: BenchScene { + let id = "locks-loading" + let title = "1024 primitives while an asset loads over and over" + let notes = "redplayer.untold loaded asynchronously, destroyed and loaded again for the whole scene; measures contention between the loader and the frame." + let orbit = LockSceneLayout.orbit + + /// Seconds a loaded asset stays in the scene before it is destroyed and the next load starts. + private let lifetime = 0.25 + + private let state = LoadState() + private var origin: simd_float3 = .zero + private var current: EntityID? + private var loadedAt: Double? + + /// Written from the loader's completion (any thread), read from the update thread. + private final class LoadState: @unchecked Sendable { + private let lock = NSLock() + private var finishedGeneration = 0 + + func markFinished(_ generation: Int) { + lock.lock() + finishedGeneration = max(finishedGeneration, generation) + lock.unlock() + } + + func hasFinished(_ generation: Int) -> Bool { + lock.lock() + defer { lock.unlock() } + return finishedGeneration >= generation + } + } + + private var generation = 0 + private var stopping = false + + func build(origin: simd_float3) { + self.origin = origin + stopping = false + _ = LockSceneLayout.buildBase(origin: origin, namePrefix: id) + startLoad() + } + + /// The load in flight, if any, is left to finish; no new one starts. + func requestStop() { + stopping = true + } + + /// False while a load is in flight: its entity must not be destroyed under the loader. + var isQuiescent: Bool { + state.hasFinished(generation) + } + + func update(deltaTime _: Float, elapsed: Double) { + guard !stopping, let entity = current, state.hasFinished(generation) else { return } + if loadedAt == nil { + loadedAt = elapsed + translateTo(entityId: entity, position: origin + simd_float3(0, 1.5, 0)) + return + } + if let loadedAt, elapsed - loadedAt >= lifetime { + destroyEntity(entityId: entity) + startLoad() + } + } + + func teardown() { + current = nil + loadedAt = nil + } + + private func startLoad() { + generation += 1 + loadedAt = nil + let entity = createEntity() + setEntityName(entityId: entity, name: "Bench Loaded \(generation)") + current = entity + let loadGeneration = generation + let state = state + // Not blocking the render loop: the point is the loader and the frame working at once. + setEntityMeshAsync(entityId: entity, filename: "redplayer", withExtension: "untold", blockRenderLoop: false) { _ in + state.markFinished(loadGeneration) + } + } +} + +/// A second thread reading the scene while the frame renders, as a render thread reads what the +/// main thread updates on visionOS. +final class LockSecondThreadScene: BenchScene { + let id = "locks-threads" + let title = "1024 primitives while a second thread reads the scene" + let notes = "A background thread reads every entity's transform in a loop while the frame runs; measures contention and wait on the scene's locks." + let orbit = LockSceneLayout.orbit + + private final class Reader: @unchecked Sendable { + private let lock = NSLock() + private var stopRequested = false + private let finished = DispatchSemaphore(value: 0) + let entities: [EntityID] + + init(entities: [EntityID]) { + self.entities = entities + } + + var shouldStop: Bool { + lock.lock() + defer { lock.unlock() } + return stopRequested + } + + func start() { + let thread = Thread { [self] in + var checksum: Float = 0 + while !shouldStop { + for entity in entities { + if let transform = scene.get(component: LocalTransformComponent.self, for: entity) { + checksum += transform.position.y + } + } + // One sweep per millisecond at most: a steady second reader, not a spin loop + // that would measure how fast a core can hammer one lock. + usleep(1000) + } + _ = checksum + finished.signal() + } + thread.name = "PerfBench Scene Reader" + thread.qualityOfService = .userInitiated + thread.start() + } + + func stopAndWait() { + lock.lock() + stopRequested = true + lock.unlock() + _ = finished.wait(timeout: .now() + 2.0) + } + } + + private var reader: Reader? + + func build(origin: simd_float3) { + let entities = LockSceneLayout.buildBase(origin: origin, namePrefix: id) + let reader = Reader(entities: entities) + self.reader = reader + reader.start() + } + + /// Stops the reader before the runner destroys the entities it reads. + func requestStop() { + reader?.stopAndWait() + reader = nil + } + + func teardown() { + requestStop() + } +} diff --git a/Examples/PerfBench/Sources/macOS/AppDelegate.swift b/Examples/PerfBench/Sources/macOS/AppDelegate.swift index 849aa21fa..d2188775c 100644 --- a/Examples/PerfBench/Sources/macOS/AppDelegate.swift +++ b/Examples/PerfBench/Sources/macOS/AppDelegate.swift @@ -50,6 +50,7 @@ final class AppDelegate: NSObject, NSApplicationDelegate { render.vsync = true render.displayRefreshHz = Double(screen?.maximumFramesPerSecond ?? 60) runner = BenchRunner(config: config, render: render) + runner.isAppActive = { NSApp.isActive } guard let renderer = UntoldRenderer.create() else { print("PERFBENCH_FAILED renderer") diff --git a/perf/baselines/Mac16_5/macOS-lockdiag/locks-api.json b/perf/baselines/Mac16_5/macOS-lockdiag/locks-api.json new file mode 100644 index 000000000..f9fa6a843 --- /dev/null +++ b/perf/baselines/Mac16_5/macOS-lockdiag/locks-api.json @@ -0,0 +1,514 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": true, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-202938-macos-r1", + "20261003-203034-macos-r2" + ], + "scene": { + "file": "locks-api.jsonl", + "id": "locks-api", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1024, + "frustumTested": 1024, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1024, + "occlusionTested": 1024, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 982, + "gpuPasses": { + "frameIndex": 982, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.046875 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.012625 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017625 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.012666 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.036792 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063292 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.097458 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.206625 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.684666 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.12625 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.12425 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.306708 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.556375 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.421666 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.296208 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.509834 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.062417 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.267917 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.122458 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.025416 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.011833 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.019709 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.011666 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.0115 + } + ], + "passesSkipped": 0, + "totalMs": 4.052830999999999 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 102, + "framesOverBudget": 6, + "framesOverBudgetLastSecond": 1, + "framesSampled": 983, + "histogram": [ + 0, + 0, + 906, + 77, + 0, + 0, + 0 + ], + "worstFrameMsLastSecond": 12.992500327527523 + }, + "locks": [ + { + "acquisitions": 97359, + "contended": 0, + "holdMs": 2.0166666666666666, + "instances": 1, + "maxHoldMs": 0.9971249999999999, + "name": "Globals.core", + "reentries": 10256, + "waitMs": 0 + }, + { + "acquisitions": 86210, + "contended": 0, + "holdMs": 0.7553333333333333, + "instances": 1, + "maxHoldMs": 0.031875, + "name": "ECS.componentIds", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 12288, + "contended": 0, + "holdMs": 0.4445, + "instances": 1, + "maxHoldMs": 0.33325, + "name": "Scene.channelRenderMode", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 1142, + "contended": 0, + "holdMs": 0.00925, + "instances": 1, + "maxHoldMs": 0.017958333333333333, + "name": "Globals.runtime", + "reentries": 0, + "waitMs": 0 + } + ], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281673728, + "isUnderPressure": false, + "meshMemoryBytes": 12089024, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 0, + "thermalState": 0, + "trackedEntityCount": 1025, + "utilizationPercent": 0.00026178339612670243 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1024, + "drawCallsShadow": 1248, + "drawCallsTotal": 2278, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 453096, + "visibleInstances": 1024 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1025, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846218.2810812085, + "timing": { + "animationMs": 0.0012082746252417564, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0006665941327810287, + "cullingMs": 0.3530415706336498, + "customSystemsMs": 0.00045832712203264236, + "encodeMs": 6.542541668750346, + "extensionsUpdateMs": 0.000625033862888813, + "frameTotalMs": 9.960291907191277, + "gameUpdateMs": 1.3684999430552125, + "geometryStreamingMs": 0.0014167744666337967, + "gpuExecutionMs": 2.702375059016049, + "gpuFrameCadenceMs": 11.179791647009552, + "lodMs": 0.0014166580513119698, + "physicsMs": 0.0007917406037449837, + "physicsStepCount": 1, + "renderPrepMs": 0.3574166912585497, + "renderTotalMs": 7.026166771538556, + "scenegraphMs": 0.1644166186451912, + "scriptingMs": 0.00024994369596242905, + "semaphoreWaitMs": 0.00037497375160455704, + "smoothedFrameMs": 10.177447274327278, + "streamingRegionMs": 0.0010833609849214554, + "submitMs": 0.006583402864634991, + "updateMs": 2.567625022493303 + } + }, + "measureSeconds": 10, + "notes": "getLocalPosition, translateTo and rotateBy on each entity per frame; measures what the public API costs in lock calls.", + "runs": 2, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 9.9844386249315, + "frameBudgetMs": 12.5, + "frames": 1974, + "framesOverBudget": 13, + "gpuPassMeanMs": { + "Block Scan Pass": 0.024265961616161576, + "Compact and Stream Pass": 0.01649651313131306, + "Copy Opaque Depth for HZB": 0.04658198989898986, + "G-Buffer + Light Pass (TBDR)": 0.65738135050505, + "Grid Pass": 0.0921942555555555, + "HZB Build Mip 0": 0.148269209090909, + "HZB Build Mip 1": 0.06149397171717173, + "HZB Build Mip 2": 0.03205492424242424, + "HZB Build Mip 3": 0.02682907171717172, + "HZB Build Mip 4": 0.02508120404040405, + "HZB Build Mip 5": 0.03334923131313133, + "HZB Build Mip 6": 0.02357698181818183, + "HZB Build Mip 7": 0.016934041414141347, + "HZB Build Mip 8": 0.01491661414141409, + "HZB Build Mip 9": 0.01461804343434337, + "HZB Occlusion Culling pass": 0.0407134242424242, + "Local Scan Pass": 0.03158425757575766, + "Mark Visible Pass": 0.017043682828282794, + "Output Transform Pass": 0.20115370202020186, + "Post-Processing Pass": 0.24809145555555578, + "Pre Composite Pass": 0.10208631111111115, + "Shadow Cascade 0": 0.14652874343434333, + "Shadow Cascade 1": 0.21950488282828284, + "Transparency Pass": 0.058879671717171705 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.016375, + "Compact and Stream Pass": 0.009541, + "Copy Opaque Depth for HZB": 0.0185, + "G-Buffer + Light Pass (TBDR)": 0.520458, + "Grid Pass": 0.059917, + "HZB Build Mip 0": 0.057958, + "HZB Build Mip 1": 0.013583, + "HZB Build Mip 2": 0.011375, + "HZB Build Mip 3": 0.00775, + "HZB Build Mip 4": 0.010125, + "HZB Build Mip 5": 0.009916, + "HZB Build Mip 6": 0.009667, + "HZB Build Mip 7": 0.009583, + "HZB Build Mip 8": 0.006833, + "HZB Build Mip 9": 0.006708, + "HZB Occlusion Culling pass": 0.030708, + "Local Scan Pass": 0.011916, + "Mark Visible Pass": 0.009042, + "Output Transform Pass": 0.093958, + "Post-Processing Pass": 0.129999, + "Pre Composite Pass": 0.053459, + "Shadow Cascade 0": 0.095417, + "Shadow Cascade 1": 0.193625, + "Transparency Pass": 0.011209 + }, + "lockCallsPerFrame": { + "ECS.componentIds": 88588.71007121057, + "Globals.core": 111611.502543235, + "Globals.runtime": 1139.6205493387588, + "Scene.channelRenderMode": 12287.426246185147 + }, + "lockContended": { + "ECS.componentIds": 0, + "Globals.core": 0, + "Globals.runtime": 3, + "Scene.channelRenderMode": 0 + }, + "lockHoldMsPerFrame": { + "ECS.componentIds": 0.772005679891488, + "Globals.core": 2.0878983129874515, + "Globals.runtime": 0.00871219057307562, + "Scene.channelRenderMode": 0.44484223465581574 + }, + "lockPerFrame": { + "ECS.componentIds": { + "calls": 88573.8809283552, + "contended": 0.0, + "holdMs": 0.771172384796501, + "waitMs": 0.0 + }, + "Globals.core": { + "calls": 111588.77800201817, + "contended": 0.0, + "holdMs": 2.0878983129874515, + "waitMs": 0.0 + }, + "Globals.runtime": { + "calls": 1139.5802219979819, + "contended": 0.0010090817356205853, + "holdMs": 0.0086220988900101, + "waitMs": 4.204507231752438e-08 + }, + "Scene.channelRenderMode": { + "calls": 12287.394550958628, + "contended": 0.0, + "holdMs": 0.44484223465581574, + "waitMs": 0.0 + } + }, + "lockWaitMs": { + "ECS.componentIds": 0, + "Globals.core": 0, + "Globals.runtime": 0.00025, + "Scene.channelRenderMode": 0 + }, + "meanFrameMs": 10.09506473691775, + "meanGPUExecutionMs": 1.7463932244220015, + "minGPUExecutionMs": 1.334875007160008, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.006103763987792472, + "p50FrameMs": 10.06820797920227, + "p95FrameMs": 11.417457833886147, + "p99FrameMs": 12.150791473686695, + "peakGPUAllocatedBytes": 281673728, + "timingMeanMs": { + "animationMs": 0.000737428920781456, + "batchingTickMs": 0.000712579242155843, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.316018750961573, + "customSystemsMs": 0.00021028325780240832, + "encodeMs": 6.587987220009712, + "extensionsUpdateMs": 0.0004389501382586453, + "gameUpdateMs": 1.3516531687692244, + "geometryStreamingMs": 0.08260981977647537, + "lodMs": 0.0010197192776335478, + "physicsMs": 0.0004075864878765991, + "renderPrepMs": 0.3197303654552709, + "renderTotalMs": 7.048875419798897, + "scenegraphMs": 0.1587513882401808, + "scriptingMs": 0.0002086722734455296, + "semaphoreWaitMs": 6.428757150526846e-05, + "streamingRegionMs": 0.0007649677815940138, + "submitMs": 0.005968843091478502, + "updateMs": 2.6146036848345044 + }, + "worstFrameMs": 15.220750123262405, + "worstThermalState": 0 + }, + "title": "1024 primitives moved through the public API every frame", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS-lockdiag/locks-loading.json b/perf/baselines/Mac16_5/macOS-lockdiag/locks-loading.json new file mode 100644 index 000000000..2e0c925ea --- /dev/null +++ b/perf/baselines/Mac16_5/macOS-lockdiag/locks-loading.json @@ -0,0 +1,514 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": true, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-202938-macos-r1", + "20261003-203034-macos-r2" + ], + "scene": { + "file": "locks-loading.jsonl", + "id": "locks-loading", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1025, + "frustumTested": 1025, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1025, + "occlusionTested": 1025, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1188, + "gpuPasses": { + "frameIndex": 1189, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.009958 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.012292 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017458 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.010625 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.033125 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063375 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.097541 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.195833 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.788834 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.030875 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.037708 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.094334 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.226042 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.191 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.104708 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.02375 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.028667 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.012875 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.015125 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.047458 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.027667 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.013167 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.0115 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.011 + } + ], + "passesSkipped": 0, + "totalMs": 2.1049170000000004 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 120, + "framesOverBudget": 8, + "framesOverBudgetLastSecond": 0, + "framesSampled": 1189, + "histogram": [ + 0, + 346, + 832, + 11, + 0, + 0, + 0 + ], + "worstFrameMsLastSecond": 10.547416284680367 + }, + "locks": [ + { + "acquisitions": 73870, + "contended": 0, + "holdMs": 1.7474999999999998, + "instances": 1, + "maxHoldMs": 0.9971249999999999, + "name": "Globals.core", + "reentries": 10266, + "waitMs": 0 + }, + { + "acquisitions": 62715, + "contended": 0, + "holdMs": 0.5510833333333334, + "instances": 1, + "maxHoldMs": 0.031875, + "name": "ECS.componentIds", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 12300, + "contended": 0, + "holdMs": 0.43966666666666665, + "instances": 1, + "maxHoldMs": 0.33325, + "name": "Scene.channelRenderMode", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 1143, + "contended": 0, + "holdMs": 0.009625, + "instances": 1, + "maxHoldMs": 0.017958333333333333, + "name": "Globals.runtime", + "reentries": 0, + "waitMs": 0 + } + ], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281985024, + "isUnderPressure": false, + "meshMemoryBytes": 12171812, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 49152, + "thermalState": 0, + "trackedEntityCount": 1026, + "utilizationPercent": 0.0002646404900588095 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1025, + "drawCallsShadow": 1248, + "drawCallsTotal": 2279, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 453396, + "visibleInstances": 1025 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1026, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846232.0628657918, + "timing": { + "animationMs": 0.0008333008736371994, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0007916241884231567, + "cullingMs": 0.31341658905148506, + "customSystemsMs": 0.0003332970663905144, + "encodeMs": 6.67449994944036, + "extensionsUpdateMs": 0.0005833571776747704, + "frameTotalMs": 8.662499487400055, + "gameUpdateMs": 0.01804158091545105, + "geometryStreamingMs": 0.0011667143553495407, + "gpuExecutionMs": 1.6307500191032887, + "gpuFrameCadenceMs": 8.694083313457668, + "lodMs": 0.0014583347365260124, + "physicsMs": 0.0007917406037449837, + "physicsStepCount": 1, + "renderPrepMs": 0.317083322443068, + "renderTotalMs": 7.586458348669112, + "scenegraphMs": 0.16179168596863747, + "scriptingMs": 0.0002916203811764717, + "semaphoreWaitMs": 0.000125030055642128, + "smoothedFrameMs": 8.321183314546943, + "streamingRegionMs": 0.0012082746252417564, + "submitMs": 0.007666647434234619, + "updateMs": 0.19041658379137516 + } + }, + "measureSeconds": 10, + "notes": "redplayer.untold loaded asynchronously, destroyed and loaded again for the whole scene; measures contention between the loader and the frame.", + "runs": 2, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 9.984420958324336, + "frameBudgetMs": 12.5, + "frames": 2377, + "framesOverBudget": 9, + "gpuPassMeanMs": { + "Block Scan Pass": 0.021567883838383733, + "Compact and Stream Pass": 0.016208478114478016, + "Copy Opaque Depth for HZB": 0.04074316232127838, + "G-Buffer + Light Pass (TBDR)": 0.6713346904962145, + "Grid Pass": 0.08303633137089979, + "HZB Build Mip 0": 0.1470732331649835, + "HZB Build Mip 1": 0.04448928114478121, + "HZB Build Mip 2": 0.032058304457527435, + "HZB Build Mip 3": 0.020011199494949516, + "HZB Build Mip 4": 0.02129016498316504, + "HZB Build Mip 5": 0.04214987973086621, + "HZB Build Mip 6": 0.026269628259041205, + "HZB Build Mip 7": 0.017020920941968054, + "HZB Build Mip 8": 0.014700827586206845, + "HZB Build Mip 9": 0.01424673423044569, + "HZB Occlusion Culling pass": 0.03732831707317065, + "Local Scan Pass": 0.032016691337258284, + "Mark Visible Pass": 0.017438583333333306, + "Output Transform Pass": 0.20270860774410768, + "Post-Processing Pass": 0.24165509932659937, + "Pre Composite Pass": 0.1035579343434342, + "Shadow Cascade 0": 0.1644881833473507, + "Shadow Cascade 1": 0.22171170731707318, + "Transparency Pass": 0.05109611531986527 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.006666, + "Compact and Stream Pass": 0.00425, + "Copy Opaque Depth for HZB": 0.011917, + "G-Buffer + Light Pass (TBDR)": 0.240583, + "Grid Pass": 0.025541, + "HZB Build Mip 0": 0.046416, + "HZB Build Mip 1": 0.008708, + "HZB Build Mip 2": 0.005833, + "HZB Build Mip 3": 0.004458, + "HZB Build Mip 4": 0.005375, + "HZB Build Mip 5": 0.004875, + "HZB Build Mip 6": 0.004375, + "HZB Build Mip 7": 0.004208, + "HZB Build Mip 8": 0.004125, + "HZB Build Mip 9": 0.004083, + "HZB Occlusion Culling pass": 0.013292, + "Local Scan Pass": 0.005208, + "Mark Visible Pass": 0.005042, + "Output Transform Pass": 0.064833, + "Post-Processing Pass": 0.076792, + "Pre Composite Pass": 0.042917, + "Shadow Cascade 0": 0.059833, + "Shadow Cascade 1": 0.078917, + "Transparency Pass": 0.00525 + }, + "lockCallsPerFrame": { + "ECS.componentIds": 65241.442388561816, + "Globals.core": 88307.56265769554, + "Globals.runtime": 1140.6425567703952, + "Scene.channelRenderMode": 12298.228763666946 + }, + "lockContended": { + "ECS.componentIds": 0, + "Globals.core": 54, + "Globals.runtime": 17, + "Scene.channelRenderMode": 0 + }, + "lockHoldMsPerFrame": { + "ECS.componentIds": 0.5746017661900757, + "Globals.core": 1.806828812727783, + "Globals.runtime": 0.009987314269694413, + "Scene.channelRenderMode": 0.4465776562938041 + }, + "lockPerFrame": { + "ECS.componentIds": { + "calls": 65241.442388561816, + "contended": 0.0, + "holdMs": 0.5746017661900757, + "waitMs": 0.0 + }, + "Globals.core": { + "calls": 88307.56265769554, + "contended": 0.037037037037037035, + "holdMs": 1.806828812727783, + "waitMs": 0.007789246632996632 + }, + "Globals.runtime": { + "calls": 1140.641414141414, + "contended": 0.014297729184188394, + "holdMs": 0.009948793490460153, + "waitMs": 1.9414073451079336e-05 + }, + "Scene.channelRenderMode": { + "calls": 12298.19696969697, + "contended": 0.0, + "holdMs": 0.4454857603815933, + "waitMs": 0.0 + } + }, + "lockWaitMs": { + "ECS.componentIds": 0, + "Globals.core": 9.975041666666666, + "Globals.runtime": 0.02308333333333333, + "Scene.channelRenderMode": 0 + }, + "meanFrameMs": 8.412510574512542, + "meanGPUExecutionMs": 1.7430722970778671, + "minGPUExecutionMs": 0.7899167248979211, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0008417508417508417, + "p50FrameMs": 8.267874829471111, + "p95FrameMs": 9.820041246712208, + "p99FrameMs": 10.534625500440598, + "peakGPUAllocatedBytes": 282034176, + "timingMeanMs": { + "animationMs": 0.0007401539296337894, + "batchingTickMs": 0.000903454273970464, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.32143229632375997, + "customSystemsMs": 0.00016533540948736658, + "encodeMs": 6.8484303100122395, + "extensionsUpdateMs": 0.0006849602408412628, + "gameUpdateMs": 0.016564325357376525, + "geometryStreamingMs": 0.08324105521861577, + "lodMs": 0.001243826962994907, + "physicsMs": 0.0003594635658104111, + "renderPrepMs": 0.3253837973560865, + "renderTotalMs": 7.735627453697452, + "scenegraphMs": 0.16175971506790632, + "scriptingMs": 0.00022007391339244715, + "semaphoreWaitMs": 8.96408748198097e-05, + "streamingRegionMs": 0.0010107689762883115, + "submitMs": 0.008049244331572242, + "updateMs": 0.18888036828246657 + }, + "worstFrameMs": 14.713332988321781, + "worstThermalState": 0 + }, + "title": "1024 primitives while an asset loads over and over", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS-lockdiag/locks-threads.json b/perf/baselines/Mac16_5/macOS-lockdiag/locks-threads.json new file mode 100644 index 000000000..40afe67e6 --- /dev/null +++ b/perf/baselines/Mac16_5/macOS-lockdiag/locks-threads.json @@ -0,0 +1,514 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": true, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-202938-macos-r1", + "20261003-203034-macos-r2" + ], + "scene": { + "file": "locks-threads.jsonl", + "id": "locks-threads", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1024, + "frustumTested": 1024, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1024, + "occlusionTested": 1024, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1019, + "gpuPasses": { + "frameIndex": 1020, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.010458 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.039708 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017709 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.010708 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.033166 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063042 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.096458 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.199125 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.613041 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.031125 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.038542 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.092834 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.224083 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.18975 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.106833 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.041458 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.015084 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.012625 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.059 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.034458 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.011875 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.011667 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.011417 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.011209 + } + ], + "passesSkipped": 0, + "totalMs": 1.9753750000000008 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 98, + "framesOverBudget": 17, + "framesOverBudgetLastSecond": 12, + "framesSampled": 1020, + "histogram": [ + 0, + 0, + 934, + 85, + 1, + 0, + 0 + ], + "worstFrameMsLastSecond": 17.321458086371422 + }, + "locks": [ + { + "acquisitions": 78918, + "contended": 2237, + "holdMs": 2.3914166666666667, + "instances": 1, + "maxHoldMs": 0.9971249999999999, + "name": "Globals.core", + "reentries": 10256, + "waitMs": 0.9974999999999999 + }, + { + "acquisitions": 67770, + "contended": 6, + "holdMs": 0.6088333333333333, + "instances": 1, + "maxHoldMs": 0.031875, + "name": "ECS.componentIds", + "reentries": 0, + "waitMs": 0.000375 + }, + { + "acquisitions": 12288, + "contended": 0, + "holdMs": 0.44608333333333333, + "instances": 1, + "maxHoldMs": 0.33325, + "name": "Scene.channelRenderMode", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 1135, + "contended": 0, + "holdMs": 0.008125, + "instances": 1, + "maxHoldMs": 0.017958333333333333, + "name": "Globals.runtime", + "reentries": 0, + "waitMs": 0 + } + ], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281690112, + "isUnderPressure": false, + "meshMemoryBytes": 12089024, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 0, + "thermalState": 0, + "trackedEntityCount": 1025, + "utilizationPercent": 0.00026178339612670243 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1024, + "drawCallsShadow": 1247, + "drawCallsTotal": 2277, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 452520, + "visibleInstances": 1024 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1025, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846245.8384064585, + "timing": { + "animationMs": 0.0007499475032091141, + "batchingRebuildMs": 0, + "batchingTickMs": 0.000625033862888813, + "cullingMs": 0.3182082436978817, + "customSystemsMs": 0, + "encodeMs": 8.094666642136872, + "extensionsUpdateMs": 0.0005416804924607277, + "frameTotalMs": 9.162500500679016, + "gameUpdateMs": 0.011791707947850227, + "geometryStreamingMs": 0.001125037670135498, + "gpuExecutionMs": 1.4540832489728928, + "gpuFrameCadenceMs": 9.64145828038454, + "lodMs": 0.0009166542440652847, + "physicsMs": 0, + "physicsStepCount": 0, + "renderPrepMs": 0.32145832665264606, + "renderTotalMs": 8.519166614860296, + "scenegraphMs": 0.1637917011976242, + "scriptingMs": 0.00020838342607021332, + "semaphoreWaitMs": 0.00016670674085617065, + "smoothedFrameMs": 9.18883333603541, + "streamingRegionMs": 0.0006667105481028557, + "submitMs": 0.007916707545518875, + "updateMs": 0.183208379894495 + } + }, + "measureSeconds": 10, + "notes": "A background thread reads every entity's transform in a loop while the frame runs; measures contention and wait on the scene's locks.", + "runs": 2, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 9.98205745825544, + "frameBudgetMs": 12.5, + "frames": 2033, + "framesOverBudget": 20, + "gpuPassMeanMs": { + "Block Scan Pass": 0.024970868627450946, + "Compact and Stream Pass": 0.017449868627450932, + "Copy Opaque Depth for HZB": 0.053628398039215645, + "G-Buffer + Light Pass (TBDR)": 0.6548021735294123, + "Grid Pass": 0.09313754999999985, + "HZB Build Mip 0": 0.18028795784313703, + "HZB Build Mip 1": 0.07423227647058825, + "HZB Build Mip 2": 0.030035881372549086, + "HZB Build Mip 3": 0.029176733333333347, + "HZB Build Mip 4": 0.024110253921568604, + "HZB Build Mip 5": 0.029564441176470606, + "HZB Build Mip 6": 0.02131565294117646, + "HZB Build Mip 7": 0.015884600980392103, + "HZB Build Mip 8": 0.014424596078431315, + "HZB Build Mip 9": 0.013755722549019562, + "HZB Occlusion Culling pass": 0.03880054411764699, + "Local Scan Pass": 0.029080851960784353, + "Mark Visible Pass": 0.025117645098039206, + "Output Transform Pass": 0.20278889509803902, + "Post-Processing Pass": 0.25089014411764715, + "Pre Composite Pass": 0.10471348137254911, + "Shadow Cascade 0": 0.16073239803921574, + "Shadow Cascade 1": 0.22691767254901968, + "Transparency Pass": 0.06663586372549016 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.006083, + "Compact and Stream Pass": 0.003917, + "Copy Opaque Depth for HZB": 0.010333, + "G-Buffer + Light Pass (TBDR)": 0.219167, + "Grid Pass": 0.021, + "HZB Build Mip 0": 0.040792, + "HZB Build Mip 1": 0.008834, + "HZB Build Mip 2": 0.008, + "HZB Build Mip 3": 0.004208, + "HZB Build Mip 4": 0.004875, + "HZB Build Mip 5": 0.009375, + "HZB Build Mip 6": 0.005083, + "HZB Build Mip 7": 0.004625, + "HZB Build Mip 8": 0.004, + "HZB Build Mip 9": 0.004167, + "HZB Occlusion Culling pass": 0.012792, + "Local Scan Pass": 0.004541, + "Mark Visible Pass": 0.004167, + "Output Transform Pass": 0.063958, + "Post-Processing Pass": 0.075583, + "Pre Composite Pass": 0.038792, + "Shadow Cascade 0": 0.034667, + "Shadow Cascade 1": 0.071375, + "Transparency Pass": 0.013084 + }, + "lockCallsPerFrame": { + "ECS.componentIds": 71256.72450980393, + "Globals.core": 94270.90098039215, + "Globals.runtime": 1139.4352941176471, + "Scene.channelRenderMode": 12287.3 + }, + "lockContended": { + "ECS.componentIds": 17046, + "Globals.core": 2615614, + "Globals.runtime": 1, + "Scene.channelRenderMode": 0 + }, + "lockHoldMsPerFrame": { + "ECS.componentIds": 0.6361942810457526, + "Globals.core": 2.6117186274509785, + "Globals.runtime": 0.00892434640522876, + "Scene.channelRenderMode": 0.4616533088235291 + }, + "lockPerFrame": { + "ECS.componentIds": { + "calls": 71256.72450980393, + "contended": 16.711764705882352, + "holdMs": 0.6361942810457526, + "waitMs": 0.008839460784313722 + }, + "Globals.core": { + "calls": 94270.90098039215, + "contended": 2564.3274509803923, + "holdMs": 2.6117186274509785, + "waitMs": 0.9040912173202604 + }, + "Globals.runtime": { + "calls": 1139.4352941176471, + "contended": 0.0, + "holdMs": 0.00892434640522876, + "waitMs": 0.0 + }, + "Scene.channelRenderMode": { + "calls": 12287.28923988154, + "contended": 0.0, + "holdMs": 0.44858102994406046, + "waitMs": 0.0 + } + }, + "lockWaitMs": { + "ECS.componentIds": 9.016249999999996, + "Globals.core": 922.1730416666657, + "Globals.runtime": 8.333333333333333e-05, + "Scene.channelRenderMode": 0 + }, + "meanFrameMs": 9.806283128758272, + "meanGPUExecutionMs": 1.799421529080171, + "minGPUExecutionMs": 0.6432500667870045, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0029615004935834156, + "p50FrameMs": 9.623666293919086, + "p95FrameMs": 11.514666490256786, + "p99FrameMs": 12.11487501859665, + "peakGPUAllocatedBytes": 281690112, + "timingMeanMs": { + "animationMs": 0.0009049005194694973, + "batchingTickMs": 0.0009926855472811296, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.41863006178330103, + "customSystemsMs": 0.00016421636603042192, + "encodeMs": 8.32093700848739, + "extensionsUpdateMs": 0.000732395496657666, + "gameUpdateMs": 0.01763847939597041, + "geometryStreamingMs": 0.10228272123426638, + "lodMs": 0.001448856817339273, + "physicsMs": 0.0004430718881768512, + "renderPrepMs": 0.42300876266776277, + "renderTotalMs": 8.94862385820506, + "scenegraphMs": 0.22377675757560805, + "scriptingMs": 0.00023415093036258921, + "semaphoreWaitMs": 0.00013545402051771388, + "streamingRegionMs": 0.001091872086273689, + "submitMs": 0.008040645123258526, + "updateMs": 0.25300437392776504 + }, + "worstFrameMs": 13.06583359837532, + "worstThermalState": 0 + }, + "title": "1024 primitives while a second thread reads the scene", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS-lockdiag/primitives-1k.json b/perf/baselines/Mac16_5/macOS-lockdiag/primitives-1k.json new file mode 100644 index 000000000..d4ec50692 --- /dev/null +++ b/perf/baselines/Mac16_5/macOS-lockdiag/primitives-1k.json @@ -0,0 +1,514 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": true, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-202938-macos-r1", + "20261003-203034-macos-r2" + ], + "scene": { + "file": "primitives-1k.jsonl", + "id": "primitives-1k", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 4, + "frustumPassed": 1020, + "frustumTested": 1024, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1020, + "occlusionTested": 1020, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1196, + "gpuPasses": { + "frameIndex": 1197, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.010125 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.03975 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017541 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.01075 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.035792 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063584 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.112833 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.199333 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.680333 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.031542 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.038959 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.093791 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.237 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.200083 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.104541 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.023875 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.028792 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.012458 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.012916 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.042041 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.019083 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.033833 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.01125 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.011708 + } + ], + "passesSkipped": 0, + "totalMs": 2.071913 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 121, + "framesOverBudget": 4, + "framesOverBudgetLastSecond": 0, + "framesSampled": 1197, + "histogram": [ + 0, + 327, + 865, + 4, + 1, + 0, + 0 + ], + "worstFrameMsLastSecond": 10.24691667407751 + }, + "locks": [ + { + "acquisitions": 74559, + "contended": 0, + "holdMs": 1.6867083333333333, + "instances": 1, + "maxHoldMs": 0.9971249999999999, + "name": "Globals.core", + "reentries": 10288, + "waitMs": 0 + }, + { + "acquisitions": 63166, + "contended": 0, + "holdMs": 0.5550833333333333, + "instances": 1, + "maxHoldMs": 0.030125, + "name": "ECS.componentIds", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 12264, + "contended": 0, + "holdMs": 0.41133333333333333, + "instances": 1, + "maxHoldMs": 0.043375, + "name": "Scene.channelRenderMode", + "reentries": 0, + "waitMs": 0 + }, + { + "acquisitions": 1138, + "contended": 0, + "holdMs": 0.008416666666666666, + "instances": 1, + "maxHoldMs": 0.013291666666666667, + "name": "Globals.runtime", + "reentries": 0, + "waitMs": 0 + } + ], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 282984448, + "isUnderPressure": false, + "meshMemoryBytes": 12098984, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 0, + "thermalState": 0, + "trackedEntityCount": 1030, + "utilizationPercent": 0.0002619990846142173 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1020, + "drawCallsShadow": 1354, + "drawCallsTotal": 2380, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 474060, + "visibleInstances": 1020 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1030, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846204.4959678336, + "timing": { + "animationMs": 0.0007499475032091141, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0007916241884231567, + "cullingMs": 0.3626249963417649, + "customSystemsMs": 0.0003332970663905144, + "encodeMs": 6.366874906234443, + "extensionsUpdateMs": 0.0007082708179950714, + "frameTotalMs": 8.55574943125248, + "gameUpdateMs": 0.01754169352352619, + "geometryStreamingMs": 0.0015416881069540977, + "gpuExecutionMs": 1.5576665755361319, + "gpuFrameCadenceMs": 8.50975001230836, + "lodMs": 0.0010833609849214554, + "physicsMs": 0.0009166542440652847, + "physicsStepCount": 1, + "renderPrepMs": 0.3725833958014846, + "renderTotalMs": 7.575833355076611, + "scenegraphMs": 0.18241663929075003, + "scriptingMs": 0.00020826701074838638, + "semaphoreWaitMs": 0.000125030055642128, + "smoothedFrameMs": 8.340079197660089, + "streamingRegionMs": 0.0009167706593871117, + "submitMs": 0.007958384230732918, + "updateMs": 0.20941661205142736 + } + }, + "measureSeconds": 10, + "notes": "One entity and draw per primitive; measures per-entity CPU cost and encoder overhead.", + "runs": 2, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 9.989957916666754, + "frameBudgetMs": 12.5, + "frames": 2397, + "framesOverBudget": 5, + "gpuPassMeanMs": { + "Block Scan Pass": 0.017783924999999975, + "Compact and Stream Pass": 0.011302940833333289, + "Copy Opaque Depth for HZB": 0.03480754250000012, + "G-Buffer + Light Pass (TBDR)": 0.702632415833332, + "Grid Pass": 0.06435915250000003, + "HZB Build Mip 0": 0.13333417583333335, + "HZB Build Mip 1": 0.054036568333333306, + "HZB Build Mip 2": 0.02703847451963242, + "HZB Build Mip 3": 0.022330261487050976, + "HZB Build Mip 4": 0.020396614870509634, + "HZB Build Mip 5": 0.030468950710108657, + "HZB Build Mip 6": 0.02159659314954051, + "HZB Build Mip 7": 0.015621734166666661, + "HZB Build Mip 8": 0.013684126666666603, + "HZB Build Mip 9": 0.012820721666666616, + "HZB Occlusion Culling pass": 0.036046140350877054, + "Local Scan Pass": 0.026337941520467877, + "Mark Visible Pass": 0.011939719166666602, + "Output Transform Pass": 0.1975791941666668, + "Post-Processing Pass": 0.23792030583333323, + "Pre Composite Pass": 0.09668797250000002, + "Shadow Cascade 0": 0.13492983000000008, + "Shadow Cascade 1": 0.19674095166666683, + "Transparency Pass": 0.04372945583333331 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.016834, + "Compact and Stream Pass": 0.010416, + "Copy Opaque Depth for HZB": 0.026084, + "G-Buffer + Light Pass (TBDR)": 0.578958, + "Grid Pass": 0.059917, + "HZB Build Mip 0": 0.05625, + "HZB Build Mip 1": 0.016292, + "HZB Build Mip 2": 0.011, + "HZB Build Mip 3": 0.010291, + "HZB Build Mip 4": 0.009875, + "HZB Build Mip 5": 0.009666, + "HZB Build Mip 6": 0.009875, + "HZB Build Mip 7": 0.009458, + "HZB Build Mip 8": 0.00925, + "HZB Build Mip 9": 0.009166, + "HZB Occlusion Culling pass": 0.033667, + "Local Scan Pass": 0.011833, + "Mark Visible Pass": 0.009667, + "Output Transform Pass": 0.157708, + "Post-Processing Pass": 0.206458, + "Pre Composite Pass": 0.082084, + "Shadow Cascade 0": 0.108541, + "Shadow Cascade 1": 0.187625, + "Transparency Pass": 0.012792 + }, + "lockCallsPerFrame": { + "ECS.componentIds": 65342.38763575606, + "Globals.core": 88527.44862155388, + "Globals.runtime": 1133.969089390142, + "Scene.channelRenderMode": 12258.300751879699 + }, + "lockContended": { + "ECS.componentIds": 0, + "Globals.core": 0, + "Globals.runtime": 5, + "Scene.channelRenderMode": 0 + }, + "lockHoldMsPerFrame": { + "ECS.componentIds": 0.5790330687830688, + "Globals.core": 1.7556366610971865, + "Globals.runtime": 0.00848802561960455, + "Scene.channelRenderMode": 0.449926482873851 + }, + "lockPerFrame": { + "ECS.componentIds": { + "calls": 65342.38763575606, + "contended": 0.0, + "holdMs": 0.5790330687830688, + "waitMs": 0.0 + }, + "Globals.core": { + "calls": 88527.44862155388, + "contended": 0.0, + "holdMs": 1.7556366610971865, + "waitMs": 0.0 + }, + "Globals.runtime": { + "calls": 1133.969089390142, + "contended": 0.0008333333333333334, + "holdMs": 0.00848802561960455, + "waitMs": 3.472222222222222e-08 + }, + "Scene.channelRenderMode": { + "calls": 12258.300751879699, + "contended": 0.0, + "holdMs": 0.449926482873851, + "waitMs": 0.0 + } + }, + "lockWaitMs": { + "ECS.componentIds": 0, + "Globals.core": 0, + "Globals.runtime": 0.002333333333333333, + "Scene.channelRenderMode": 0 + }, + "meanFrameMs": 8.339462237199768, + "meanGPUExecutionMs": 1.6833340293184544, + "minGPUExecutionMs": 1.4784999657422304, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0008333333333333334, + "p50FrameMs": 8.27016681432724, + "p95FrameMs": 9.831208735704422, + "p99FrameMs": 10.230083018541336, + "peakGPUAllocatedBytes": 282984448, + "timingMeanMs": { + "animationMs": 0.0006719930027436493, + "batchingTickMs": 0.0008517824138266501, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.3159968294288867, + "customSystemsMs": 0.00015013151371862457, + "encodeMs": 6.634726503602507, + "extensionsUpdateMs": 0.0005901563382001848, + "gameUpdateMs": 0.01463034840223069, + "geometryStreamingMs": 0.07924996481767996, + "lodMs": 0.00116328968306258, + "physicsMs": 0.0003312169186150034, + "renderPrepMs": 0.31988091927111995, + "renderTotalMs": 7.709203089762013, + "scenegraphMs": 0.16137691393242518, + "scriptingMs": 0.0002011620776483489, + "semaphoreWaitMs": 0.00011072769907358396, + "streamingRegionMs": 0.0009346640931011342, + "submitMs": 0.007622803498367618, + "updateMs": 0.1862952164736084 + }, + "worstFrameMs": 15.028875321149826, + "worstThermalState": 0 + }, + "title": "1024 primitives, 4 point lights", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS/locks-api.json b/perf/baselines/Mac16_5/macOS/locks-api.json new file mode 100644 index 000000000..dc4493d12 --- /dev/null +++ b/perf/baselines/Mac16_5/macOS/locks-api.json @@ -0,0 +1,428 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": false, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-203345-macos-r1", + "20261003-203443-macos-r2", + "20261003-203540-macos-r3" + ], + "scene": { + "file": "locks-api.jsonl", + "id": "locks-api", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1024, + "frustumTested": 1024, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1024, + "occlusionTested": 1024, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1723, + "gpuPasses": { + "frameIndex": 1723, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.010917 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.012708 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017333 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.011208 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.036 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.061708 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.131292 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.19525 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.672333 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.030417 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.037084 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.093667 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.219458 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.183916 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.104333 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.024333 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.027667 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.01375 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.036833 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.031125 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.012709 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.041625 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.011334 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.011166 + } + ], + "passesSkipped": 0, + "totalMs": 2.0281659999999997 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 109, + "framesOverBudget": 11, + "framesOverBudgetLastSecond": 0, + "framesSampled": 1724, + "histogram": [ + 0, + 47, + 1645, + 29, + 3, + 0, + 0 + ], + "worstFrameMsLastSecond": 11.535458266735077 + }, + "locks": [], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281935872, + "isUnderPressure": false, + "meshMemoryBytes": 12091016, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 0, + "thermalState": 0, + "trackedEntityCount": 1026, + "utilizationPercent": 0.0002618265280034393 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1024, + "drawCallsShadow": 1491, + "drawCallsTotal": 2521, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 501696, + "visibleInstances": 1024 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1026, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846457.0879912085, + "timing": { + "animationMs": 0.000250060111284256, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0003332970663905144, + "cullingMs": 0.24316669441759586, + "customSystemsMs": 0.0003332970663905144, + "encodeMs": 5.3102916572242975, + "extensionsUpdateMs": 0.00016659032553434372, + "frameTotalMs": 8.221208117902279, + "gameUpdateMs": 1.0392500553280115, + "geometryStreamingMs": 0.00037497375160455704, + "gpuExecutionMs": 1.607874990440905, + "gpuFrameCadenceMs": 8.218999952077866, + "lodMs": 0.0005416804924607277, + "physicsMs": 0.0006249174475669861, + "physicsStepCount": 1, + "renderPrepMs": 0.24508335627615452, + "renderTotalMs": 5.628833314403892, + "scenegraphMs": 0.11725001968443394, + "scriptingMs": 0.000125030055642128, + "semaphoreWaitMs": 8.335337042808533e-05, + "smoothedFrameMs": 8.836106987049183, + "streamingRegionMs": 0.0002916203811764717, + "submitMs": 0.00341667328029871, + "updateMs": 2.2373750107362866 + } + }, + "measureSeconds": 15, + "notes": "getLocalPosition, translateTo and rotateBy on each entity per frame; measures what the public API costs in lock calls.", + "runs": 3, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 14.98943720839452, + "frameBudgetMs": 12.5, + "frames": 5229, + "framesOverBudget": 48, + "gpuPassMeanMs": { + "Block Scan Pass": 0.02062249622751018, + "Compact and Stream Pass": 0.01594172947131615, + "Copy Opaque Depth for HZB": 0.038059421449275384, + "G-Buffer + Light Pass (TBDR)": 0.6499929384793968, + "Grid Pass": 0.07127251687289081, + "HZB Build Mip 0": 0.11924327742309912, + "HZB Build Mip 1": 0.03581654893138366, + "HZB Build Mip 2": 0.028715263188405952, + "HZB Build Mip 3": 0.01771272890888642, + "HZB Build Mip 4": 0.022650147826087014, + "HZB Build Mip 5": 0.03757311188405802, + "HZB Build Mip 6": 0.02438558260869568, + "HZB Build Mip 7": 0.015432011014492767, + "HZB Build Mip 8": 0.012669118260869538, + "HZB Build Mip 9": 0.011984645217391262, + "HZB Occlusion Culling pass": 0.037544020313406826, + "Local Scan Pass": 0.018175605797101483, + "Mark Visible Pass": 0.02380199419616953, + "Output Transform Pass": 0.19287784213580939, + "Post-Processing Pass": 0.23434674114915863, + "Pre Composite Pass": 0.09700620893789906, + "Shadow Cascade 0": 0.12556755426581553, + "Shadow Cascade 1": 0.20346098666666668, + "Transparency Pass": 0.04489842840579708 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.00675, + "Compact and Stream Pass": 0.004167, + "Copy Opaque Depth for HZB": 0.0125, + "G-Buffer + Light Pass (TBDR)": 0.241167, + "Grid Pass": 0.023125, + "HZB Build Mip 0": 0.042125, + "HZB Build Mip 1": 0.009458, + "HZB Build Mip 2": 0.006084, + "HZB Build Mip 3": 0.004917, + "HZB Build Mip 4": 0.004791, + "HZB Build Mip 5": 0.004875, + "HZB Build Mip 6": 0.005084, + "HZB Build Mip 7": 0.004958, + "HZB Build Mip 8": 0.004334, + "HZB Build Mip 9": 0.004459, + "HZB Occlusion Culling pass": 0.014292, + "Local Scan Pass": 0.004792, + "Mark Visible Pass": 0.004167, + "Output Transform Pass": 0.066917, + "Post-Processing Pass": 0.080626, + "Pre Composite Pass": 0.036375, + "Shadow Cascade 0": 0.037833, + "Shadow Cascade 1": 0.075334, + "Transparency Pass": 0.015792 + }, + "lockCallsPerFrame": {}, + "lockContended": {}, + "lockHoldMsPerFrame": {}, + "lockWaitMs": {}, + "meanFrameMs": 8.434032861398823, + "meanGPUExecutionMs": 1.6168337911924155, + "minGPUExecutionMs": 0.6831249920651317, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0016863406408094434, + "p50FrameMs": 8.44774954020977, + "p95FrameMs": 9.611833840608597, + "p99FrameMs": 10.33687498420477, + "peakGPUAllocatedBytes": 281935872, + "timingMeanMs": { + "animationMs": 0.0004326645127838418, + "batchingTickMs": 0.000504425691755854, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.2538314120066072, + "customSystemsMs": 0.00013675763962257438, + "encodeMs": 5.413460652364869, + "extensionsUpdateMs": 0.0002581512706250606, + "gameUpdateMs": 1.0913650423808028, + "geometryStreamingMs": 0.06196802801872955, + "lodMs": 0.00074297344671199, + "physicsMs": 0.0002840556101711229, + "renderPrepMs": 0.25667659638626494, + "renderTotalMs": 5.8202516610701185, + "scenegraphMs": 0.12127119657008198, + "scriptingMs": 0.0001112052290258011, + "semaphoreWaitMs": 2.559952640999161e-05, + "streamingRegionMs": 0.0005813907468592001, + "submitMs": 0.005128956098840303, + "updateMs": 2.2792590398767105 + }, + "worstFrameMs": 17.434459179639816, + "worstThermalState": 0 + }, + "title": "1024 primitives moved through the public API every frame", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS/locks-loading.json b/perf/baselines/Mac16_5/macOS/locks-loading.json new file mode 100644 index 000000000..86dcfb449 --- /dev/null +++ b/perf/baselines/Mac16_5/macOS/locks-loading.json @@ -0,0 +1,428 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": false, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-203345-macos-r1", + "20261003-203443-macos-r2", + "20261003-203540-macos-r3" + ], + "scene": { + "file": "locks-loading.jsonl", + "id": "locks-loading", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1025, + "frustumTested": 1025, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1025, + "occlusionTested": 1025, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1746, + "gpuPasses": { + "frameIndex": 1747, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.010375 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.039833 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017542 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.011292 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.033041 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063125 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.13825 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.206375 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.653291 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.031458 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.037583 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.092709 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.22879200000000002 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.195792 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.156042 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.158083 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.014875 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.021958 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.012584 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.012125 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.013834 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.01175 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.011459 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.011208 + } + ], + "passesSkipped": 0, + "totalMs": 2.183376 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 118, + "framesOverBudget": 126, + "framesOverBudgetLastSecond": 7, + "framesSampled": 1747, + "histogram": [ + 0, + 931, + 535, + 274, + 7, + 0, + 0 + ], + "worstFrameMsLastSecond": 15.610291622579098 + }, + "locks": [], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281985024, + "isUnderPressure": false, + "meshMemoryBytes": 12171812, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 49152, + "thermalState": 0, + "trackedEntityCount": 1026, + "utilizationPercent": 0.0002646404900588095 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1025, + "drawCallsShadow": 1490, + "drawCallsTotal": 2521, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 502974, + "visibleInstances": 1025 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1026, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846475.8666550835, + "timing": { + "animationMs": 0.0005833571776747704, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0009583309292793274, + "cullingMs": 0.25949999690055847, + "customSystemsMs": 0.0003332970663905144, + "encodeMs": 5.8261250378564, + "extensionsUpdateMs": 0.0006249174475669861, + "frameTotalMs": 9.451916441321373, + "gameUpdateMs": 0.017166603356599808, + "geometryStreamingMs": 0.0012082746252417564, + "gpuExecutionMs": 1.6276249662041664, + "gpuFrameCadenceMs": 9.524875087663531, + "lodMs": 0.0012083910405635834, + "physicsMs": 0.000750063918530941, + "physicsStepCount": 1, + "renderPrepMs": 0.26370829436928034, + "renderTotalMs": 6.883875001221895, + "scenegraphMs": 0.12170837726444006, + "scriptingMs": 0.000250060111284256, + "semaphoreWaitMs": 0.00016670674085617065, + "smoothedFrameMs": 8.333820849657059, + "streamingRegionMs": 0.0010416842997074127, + "submitMs": 0.009124982170760632, + "updateMs": 0.14824990648776293 + } + }, + "measureSeconds": 15, + "notes": "redplayer.untold loaded asynchronously, destroyed and loaded again for the whole scene; measures contention between the loader and the frame.", + "runs": 3, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 14.98123804165516, + "frameBudgetMs": 12.5, + "frames": 5329, + "framesOverBudget": 198, + "gpuPassMeanMs": { + "Block Scan Pass": 0.017773172222222116, + "Compact and Stream Pass": 0.011354680555555514, + "Copy Opaque Depth for HZB": 0.031966344444444426, + "G-Buffer + Light Pass (TBDR)": 0.6595541038888904, + "Grid Pass": 0.06274401222222217, + "HZB Build Mip 0": 0.11416655333333327, + "HZB Build Mip 1": 0.03004227055555561, + "HZB Build Mip 2": 0.02924838277777779, + "HZB Build Mip 3": 0.015465547222222225, + "HZB Build Mip 4": 0.01868300055555559, + "HZB Build Mip 5": 0.04048470482603814, + "HZB Build Mip 6": 0.026446470819304152, + "HZB Build Mip 7": 0.016048772777777814, + "HZB Build Mip 8": 0.013066498333333327, + "HZB Build Mip 9": 0.011977563333333335, + "HZB Occlusion Culling pass": 0.03363012999999986, + "Local Scan Pass": 0.014134301111111093, + "Mark Visible Pass": 0.03206299313108186, + "Output Transform Pass": 0.18950714277777783, + "Post-Processing Pass": 0.22709796277777805, + "Pre Composite Pass": 0.10200037833333332, + "Shadow Cascade 0": 0.11659577055555567, + "Shadow Cascade 1": 0.19974458500000009, + "Transparency Pass": 0.03959459499999999 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.009541, + "Compact and Stream Pass": 0.005916, + "Copy Opaque Depth for HZB": 0.01575, + "G-Buffer + Light Pass (TBDR)": 0.338625, + "Grid Pass": 0.033833, + "HZB Build Mip 0": 0.057167, + "HZB Build Mip 1": 0.013333, + "HZB Build Mip 2": 0.00825, + "HZB Build Mip 3": 0.006917, + "HZB Build Mip 4": 0.007042, + "HZB Build Mip 5": 0.007042, + "HZB Build Mip 6": 0.007, + "HZB Build Mip 7": 0.006625, + "HZB Build Mip 8": 0.006208, + "HZB Build Mip 9": 0.006416, + "HZB Occlusion Culling pass": 0.01875, + "Local Scan Pass": 0.006834, + "Mark Visible Pass": 0.00625, + "Output Transform Pass": 0.097291, + "Post-Processing Pass": 0.11762500000000001, + "Pre Composite Pass": 0.051667, + "Shadow Cascade 0": 0.062459, + "Shadow Cascade 1": 0.109042, + "Transparency Pass": 0.02 + }, + "lockCallsPerFrame": {}, + "lockContended": {}, + "lockHoldMsPerFrame": {}, + "lockWaitMs": {}, + "meanFrameMs": 8.333052526642051, + "meanGPUExecutionMs": 1.5559118301866368, + "minGPUExecutionMs": 0.8770000422373414, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0, + "p50FrameMs": 7.667583413422108, + "p95FrameMs": 9.462375193834305, + "p99FrameMs": 10.126791894435883, + "peakGPUAllocatedBytes": 282034176, + "timingMeanMs": { + "animationMs": 0.0003631466016587284, + "batchingTickMs": 0.0005903925436238447, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.24678085717217377, + "customSystemsMs": 0.00012797035912405093, + "encodeMs": 5.524509907764797, + "extensionsUpdateMs": 0.00038531067437261307, + "gameUpdateMs": 0.01216535421827212, + "geometryStreamingMs": 0.06092173629440367, + "lodMs": 0.0008996301201275653, + "physicsMs": 0.0002754398802709248, + "renderPrepMs": 0.24954557897419566, + "renderTotalMs": 7.855499398105571, + "scenegraphMs": 0.12005275600434591, + "scriptingMs": 0.0001082353489358484, + "semaphoreWaitMs": 6.584377434652395e-05, + "streamingRegionMs": 0.0006450225676720341, + "submitMs": 0.006022560623440834, + "updateMs": 0.14000499989682189 + }, + "worstFrameMs": 11.94437500089407, + "worstThermalState": 0 + }, + "title": "1024 primitives while an asset loads over and over", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/perf/baselines/Mac16_5/macOS/locks-threads.json b/perf/baselines/Mac16_5/macOS/locks-threads.json new file mode 100644 index 000000000..79e31078e --- /dev/null +++ b/perf/baselines/Mac16_5/macOS/locks-threads.json @@ -0,0 +1,428 @@ +{ + "device": { + "gpuName": "Apple M4 Max", + "isLowPowerMode": false, + "model": "Mac16,5", + "osVersion": "Version 27.0 (Build 26A428)", + "physicalMemoryBytes": 137438953472, + "processorCount": 16, + "thermalStateAtStart": 0 + }, + "label": "v0.21.0-256-g45621f72-dirty", + "render": { + "antiAliasing": "fxaa", + "displayRefreshHz": 120, + "foveation": false, + "immersion": "none", + "layout": "single", + "lockDiagnostics": false, + "platform": "macOS", + "renderQuality": 1, + "viewCount": 1, + "viewportHeight": 1080, + "viewportWidth": 1920, + "vsync": true, + "xrFramePacing": false + }, + "runIDs": [ + "20261003-203345-macos-r1", + "20261003-203443-macos-r2", + "20261003-203540-macos-r3" + ], + "scene": { + "file": "locks-threads.jsonl", + "id": "locks-threads", + "lastSnapshot": { + "batching": { + "batchGroupCount": 0, + "batchedMeshCount": 0, + "deferredByWorkBudget": 0, + "dirtyCellsAfterPrune": 0, + "dirtyCellsBeforePrune": 0, + "dispatchedBuilds": 0, + "lastRebuildCostMs": 0, + "lastRebuildInputMeshCount": 0, + "lastRebuildOutputBatchCount": 0, + "rebuildsThisSecond": 0, + "skippedByComplexityGuard": 0 + }, + "compositor": { + "deadlineMarginMs": 0, + "deadlineSampleCount": 0, + "earlyStartMs": 0, + "inputSlackMs": 0, + "missedDeadline": false, + "missedDeadlineCount": 0, + "missingAnchorCount": 0, + "presentationMarginMs": 0, + "submissionMs": 0, + "updateMs": 0, + "viewCount": 0, + "viewTextureHeight": 0, + "viewTextureWidth": 0 + }, + "culling": { + "frustumFailed": 0, + "frustumPassed": 1024, + "frustumTested": 1024, + "hzbIsValid": true, + "hzbMipCount": 10, + "occlusionFailed": 0, + "occlusionPassed": 1024, + "occlusionTested": 1024, + "optimizedFrustumPath": true, + "selectedHZBMipLevel": 0, + "selectedHZBMipSize": [ + 960, + 540 + ], + "usedHZB": true + }, + "frameIndex": 1786, + "gpuPasses": { + "frameIndex": 1787, + "passes": [ + { + "count": 1, + "label": "Mark Visible Pass", + "ms": 0.046916 + }, + { + "count": 1, + "label": "Local Scan Pass", + "ms": 0.012542 + }, + { + "count": 1, + "label": "Block Scan Pass", + "ms": 0.017667 + }, + { + "count": 1, + "label": "Compact and Stream Pass", + "ms": 0.01075 + }, + { + "count": 1, + "label": "HZB Occlusion Culling pass", + "ms": 0.033084 + }, + { + "count": 1, + "label": "Grid Pass", + "ms": 0.063792 + }, + { + "count": 1, + "label": "Shadow Cascade 0", + "ms": 0.146917 + }, + { + "count": 1, + "label": "Shadow Cascade 1", + "ms": 0.284209 + }, + { + "count": 1, + "label": "G-Buffer + Light Pass (TBDR)", + "ms": 0.684708 + }, + { + "count": 1, + "label": "Copy Opaque Depth for HZB", + "ms": 0.031125 + }, + { + "count": 1, + "label": "Transparency Pass", + "ms": 0.037958 + }, + { + "count": 1, + "label": "Pre Composite Pass", + "ms": 0.093167 + }, + { + "count": 2, + "label": "Post-Processing Pass", + "ms": 0.21795799999999999 + }, + { + "count": 1, + "label": "Output Transform Pass", + "ms": 0.182 + }, + { + "count": 1, + "label": "HZB Build Mip 0", + "ms": 0.103458 + }, + { + "count": 1, + "label": "HZB Build Mip 1", + "ms": 0.025208 + }, + { + "count": 1, + "label": "HZB Build Mip 2", + "ms": 0.027709 + }, + { + "count": 1, + "label": "HZB Build Mip 3", + "ms": 0.013125 + }, + { + "count": 1, + "label": "HZB Build Mip 4", + "ms": 0.016833 + }, + { + "count": 1, + "label": "HZB Build Mip 5", + "ms": 0.050417 + }, + { + "count": 1, + "label": "HZB Build Mip 6", + "ms": 0.035083 + }, + { + "count": 1, + "label": "HZB Build Mip 7", + "ms": 0.011542 + }, + { + "count": 1, + "label": "HZB Build Mip 8", + "ms": 0.011333 + }, + { + "count": 1, + "label": "HZB Build Mip 9", + "ms": 0.0115 + } + ], + "passesSkipped": 0, + "totalMs": 2.169001 + }, + "hitches": { + "frameBudgetMs": 12.5, + "framesLastSecond": 115, + "framesOverBudget": 31, + "framesOverBudgetLastSecond": 6, + "framesSampled": 1787, + "histogram": [ + 0, + 987, + 706, + 92, + 2, + 0, + 0 + ], + "worstFrameMsLastSecond": 19.102083519101143 + }, + "locks": [], + "memory": { + "availableMemoryBytes": 0, + "geometryBudgetBytes": 27707694120, + "gpuAllocatedBytes": 281673728, + "isUnderPressure": false, + "meshMemoryBytes": 12089024, + "textureBudgetBytes": 18471796080, + "textureMemoryBytes": 0, + "thermalState": 0, + "trackedEntityCount": 1025, + "utilizationPercent": 0.00026178339612670243 + }, + "render": { + "drawCallsBatched": 0, + "drawCallsOpaque": 1024, + "drawCallsShadow": 1488, + "drawCallsTotal": 2518, + "drawCallsTransparent": 0, + "tileFullDrawsEstimate": 0, + "tileFullTrianglesEstimate": 0, + "tileFullVisibleInstances": 0, + "tileHLODDrawsEstimate": 0, + "tileHLODTrianglesEstimate": 0, + "tileHLODVisibleInstances": 0, + "tileLODDrawsEstimate": 0, + "tileLODTrianglesEstimate": 0, + "tileLODVisibleInstances": 0, + "trianglesTotal": 501660, + "visibleInstances": 1024 + }, + "streaming": { + "activeLoads": 0, + "activeTileRepresentationFades": 0, + "availableLoadSlots": 3, + "averageAsyncLoadMs": 0, + "blockedByGateMs": 0, + "cachedMeshResources": 0, + "evictionsPerformed": 0, + "fullAndFallbackResidentOverlapTiles": 0, + "fullAndHLODVisibleOverlapTiles": 0, + "fullAndLODVisibleOverlapTiles": 0, + "lastApplyLoadedMeshMs": 0, + "loadCandidates": 0, + "loadedStreamingEntities": 0, + "loadingStreamingEntities": 0, + "lod0VisibilityWarnings": 0, + "lod0VisibilityWarningsNoFallback": 0, + "lod0VisibilityWarningsWithFallback": 0, + "lodAndHLODVisibleOverlapTiles": 0, + "nearbyEntitiesQueried": 1025, + "pendingLoadBacklog": 0, + "pendingUploadCount": 0, + "residentFullTileRepresentations": 0, + "residentHLODRepresentations": 0, + "residentLODRepresentations": 0, + "residentMeshEntities": 0, + "tileRepresentationGapWarnings": 0, + "tileSwapWarnings": 0, + "tilesSkippedByHierarchyGate": 0, + "unloadedStreamingEntities": 0, + "updateTriggered": false, + "updateWorkMs": 0, + "visibleFullTileRepresentations": 0, + "visibleHLODRepresentations": 0, + "visibleLODRepresentations": 0, + "waitingTileRepresentationFades": 0 + }, + "timestampSeconds": 846494.6517511252, + "timing": { + "animationMs": 0.00037497375160455704, + "batchingRebuildMs": 0, + "batchingTickMs": 0.0005416804924607277, + "cullingMs": 0.3363334108144045, + "customSystemsMs": 0.00029173679649829865, + "encodeMs": 6.51824998203665, + "extensionsUpdateMs": 0.00037509016692638397, + "frameTotalMs": 10.143125429749489, + "gameUpdateMs": 0.010583316907286644, + "geometryStreamingMs": 0.0006667105481028557, + "gpuExecutionMs": 1.6690000193193555, + "gpuFrameCadenceMs": 10.251791682094336, + "lodMs": 0.0010833609849214554, + "physicsMs": 0.000500003807246685, + "physicsStepCount": 1, + "renderPrepMs": 0.34491659607738256, + "renderTotalMs": 6.954749929718673, + "scenegraphMs": 0.13929163105785847, + "scriptingMs": 8.335337042808533e-05, + "semaphoreWaitMs": 0.00016659032553434372, + "smoothedFrameMs": 8.607158421849212, + "streamingRegionMs": 0.0005833571776747704, + "submitMs": 0.004791654646396637, + "updateMs": 0.1565832644701004 + } + }, + "measureSeconds": 15, + "notes": "A background thread reads every entity's transform in a loop while the frame runs; measures contention and wait on the scene's locks.", + "runs": 3, + "summary": { + "deadlineSamples": 0, + "durationSeconds": 14.989616333390586, + "frameBudgetMs": 12.5, + "frames": 5384, + "framesOverBudget": 41, + "gpuPassMeanMs": { + "Block Scan Pass": 0.01810296499999986, + "Compact and Stream Pass": 0.011430185555555486, + "Copy Opaque Depth for HZB": 0.03455152999999996, + "G-Buffer + Light Pass (TBDR)": 0.6484877333333341, + "Grid Pass": 0.06378498166666666, + "HZB Build Mip 0": 0.12344351888888888, + "HZB Build Mip 1": 0.035434395555555546, + "HZB Build Mip 2": 0.02982825500000005, + "HZB Build Mip 3": 0.0168272, + "HZB Build Mip 4": 0.02225621555555556, + "HZB Build Mip 5": 0.03477382428651378, + "HZB Build Mip 6": 0.02329458310016787, + "HZB Build Mip 7": 0.01574104674457429, + "HZB Build Mip 8": 0.013256831666666675, + "HZB Build Mip 9": 0.01210790666666664, + "HZB Occlusion Culling pass": 0.03376225888888885, + "Local Scan Pass": 0.01467613888888891, + "Mark Visible Pass": 0.02521390598768888, + "Output Transform Pass": 0.1938110433333335, + "Post-Processing Pass": 0.23496454888888896, + "Pre Composite Pass": 0.10370712500000007, + "Shadow Cascade 0": 0.11945248222222205, + "Shadow Cascade 1": 0.20104481277777753, + "Transparency Pass": 0.041832037222222195 + }, + "gpuPassMinMs": { + "Block Scan Pass": 0.016792, + "Compact and Stream Pass": 0.010209, + "Copy Opaque Depth for HZB": 0.025583, + "G-Buffer + Light Pass (TBDR)": 0.541166, + "Grid Pass": 0.059541, + "HZB Build Mip 0": 0.057916, + "HZB Build Mip 1": 0.016417, + "HZB Build Mip 2": 0.010875, + "HZB Build Mip 3": 0.010167, + "HZB Build Mip 4": 0.01, + "HZB Build Mip 5": 0.009958, + "HZB Build Mip 6": 0.009958, + "HZB Build Mip 7": 0.009458, + "HZB Build Mip 8": 0.009167, + "HZB Build Mip 9": 0.009166, + "HZB Occlusion Culling pass": 0.031375, + "Local Scan Pass": 0.011875, + "Mark Visible Pass": 0.009666, + "Output Transform Pass": 0.167333, + "Post-Processing Pass": 0.205708, + "Pre Composite Pass": 0.089208, + "Shadow Cascade 0": 0.093541, + "Shadow Cascade 1": 0.187125, + "Transparency Pass": 0.031834 + }, + "lockCallsPerFrame": {}, + "lockContended": {}, + "lockHoldMsPerFrame": {}, + "lockWaitMs": {}, + "meanFrameMs": 8.333650084160682, + "meanGPUExecutionMs": 1.5604869921743456, + "minGPUExecutionMs": 1.4083749847486615, + "missedDeadlineRate": 0.0, + "missedDeadlines": 0, + "overBudgetRate": 0.0005555555555555556, + "p50FrameMs": 7.862875238060951, + "p95FrameMs": 9.829333052039146, + "p99FrameMs": 10.281750001013279, + "peakGPUAllocatedBytes": 281673728, + "timingMeanMs": { + "animationMs": 0.0004296754131847179, + "batchingTickMs": 0.0005640036478224727, + "compositorDeadlineMarginMs": 0, + "compositorEarlyStartMs": 0, + "compositorInputSlackMs": 0, + "compositorSubmissionMs": 0, + "compositorUpdateMs": 0, + "cullingMs": 0.34473729198699515, + "customSystemsMs": 0.00012131383498476556, + "encodeMs": 6.561742154493307, + "extensionsUpdateMs": 0.00031510757724974775, + "gameUpdateMs": 0.009467654201239928, + "geometryStreamingMs": 0.09041841553079061, + "lodMs": 0.0009128940291702747, + "physicsMs": 0.0002885190123278234, + "renderPrepMs": 0.34772987662755667, + "renderTotalMs": 7.692250484704143, + "scenegraphMs": 0.18282055439949702, + "scriptingMs": 8.660263413512581e-05, + "semaphoreWaitMs": 5.332968401441192e-05, + "streamingRegionMs": 0.0005892456421586097, + "submitMs": 0.0054030786706347166, + "updateMs": 0.20073107925736547 + }, + "worstFrameMs": 12.950041331350803, + "worstThermalState": 0 + }, + "title": "1024 primitives while a second thread reads the scene", + "warmupSeconds": 3 + } +} \ No newline at end of file diff --git a/scripts/perf/compare_baseline.py b/scripts/perf/compare_baseline.py index be35ac8b4..e6691dd6b 100755 --- a/scripts/perf/compare_baseline.py +++ b/scripts/perf/compare_baseline.py @@ -5,6 +5,11 @@ app wrote it, so a baseline is only ever compared with the same platform, layout, foveation and viewport. Exit status 1 means at least one metric regressed past its threshold. +A run of a build with ENGINE_LOCK_DIAGNOSTICS (render.lockDiagnostics) has its own baselines, in +perf/baselines//-lockdiag/, and is judged on its lock numbers only: lock calls +per frame and time spent waiting for a lock per frame, per lock name. Its frame and CPU times +carry the instrumentation and are not judged. + Several summaries may be given (repeated runs): every time metric and every rate is aggregated by its minimum across runs. On a lightly loaded machine CPU and GPU clocks drift between runs, and other activity on the machine makes it skip refreshes; both only ever inflate a time or a rate, so @@ -16,11 +21,21 @@ it is on a headset, and reported as information otherwise. A GPU or CPU time also only counts as changed when it moves by more than the relative tolerance and by more than an absolute slack. +The same holds for small CPU times: a system that takes a fraction of a millisecond in a scene +that leaves the CPU idle runs at whatever clock and core the scheduler picks, and measured 0.2 and +0.8 ms in consecutive runs of the same build. A per-system CPU mean is judged only when the +baseline's value is at least --cpu-floor-ms. Each scene also carries how many CPU cores other +processes used while it was recorded. When even the quietest run had --busy-cores or more, the +scene is marked and its frame pacing (frame percentiles, over-budget and missed-deadline rates) is +reported as information: skipped refreshes and long frames are then the machine's, not the +engine's. The CPU means of the heavier systems are still judged; they hold up under that load. + compare_baseline.py perf/results//summary.json [more summary.json ...] [--baselines DIR] [--update] [--time-tolerance 0.10] [--rate-tolerance 0.005] [--pass-tolerance 0.20] [--gpu-slack-ms 0.5] [--pass-slack-ms 0.25] [--cpu-slack-ms 0.1] - [--gpu-busy-fraction 0.5] + [--gpu-busy-fraction 0.5] [--cpu-floor-ms 1.0] [--busy-cores 1.0] + [--lock-call-tolerance 0.03] [--lock-wait-tolerance 0.25] [--lock-wait-slack-ms 0.05] """ import argparse import json @@ -116,10 +131,36 @@ def aggregate(scenes): merged[label] = min(merged.get(label, value), value) s[field] = merged s["worstThermalState"] = max(x["summary"].get("worstThermalState", 0) for x in scenes) + first["otherProcessLoadCores"] = min(x.get("otherProcessLoadCores", 0.0) for x in scenes) + locks = [lock_metrics(x["summary"]) for x in scenes] + if any(locks): + merged = {} + for per_run in locks: + for name, values in per_run.items(): + best = merged.setdefault(name, dict(values)) + for key, value in values.items(): + best[key] = min(best[key], value) + s["lockPerFrame"] = merged first["runs"] = len(scenes) return first +def lock_metrics(summary): + """Per lock name: calls, hold ms, contended acquisitions and wait ms, each per frame.""" + if "lockPerFrame" in summary: + return summary["lockPerFrame"] + frames = max(1, summary.get("frames", 0)) + result = {} + for name, calls in summary.get("lockCallsPerFrame", {}).items(): + result[name] = { + "calls": calls, + "holdMs": summary.get("lockHoldMsPerFrame", {}).get(name, 0.0), + "contended": summary.get("lockContended", {}).get(name, 0) / frames, + "waitMs": summary.get("lockWaitMs", {}).get(name, 0.0) / frames, + } + return result + + def main(): ap = argparse.ArgumentParser() ap.add_argument("summaries", nargs="+") @@ -133,6 +174,13 @@ def main(): ap.add_argument("--cpu-slack-ms", type=float, default=0.1, help="a per-system CPU mean must also move by more than this") ap.add_argument("--gpu-busy-fraction", type=float, default=0.5, help="judge GPU times only when the baseline's mean GPU time is at least this fraction of its mean frame time") + ap.add_argument("--cpu-floor-ms", type=float, default=1.0, + help="judge a per-system CPU mean only when the baseline's value is at least this") + ap.add_argument("--busy-cores", type=float, default=1.0, + help="mark a scene when other processes used at least this many cores in its quietest run") + ap.add_argument("--lock-call-tolerance", type=float, default=0.03, help="relative slack for lock calls per frame") + ap.add_argument("--lock-wait-tolerance", type=float, default=0.25, help="relative slack for lock wait time per frame") + ap.add_argument("--lock-wait-slack-ms", type=float, default=0.05, help="lock wait time per frame must also move by more than this") args = ap.parse_args() runs = [load(p) for p in args.summaries] @@ -149,10 +197,12 @@ def main(): model = safe_model(first["device"]["model"]) platform = first["render"]["platform"] - base_dir = os.path.join(args.baselines, model, platform) + lock_mode = bool(first["render"].get("lockDiagnostics", False)) + base_dir = os.path.join(args.baselines, model, platform + ("-lockdiag" if lock_mode else "")) r = first["render"] print(f"{len(runs)} run(s), label={first.get('label','')!r} device={first['device']['model']} platform={platform} " - f"viewport={r.get('viewportWidth')}x{r.get('viewportHeight')} x{r.get('viewCount')} refresh={r.get('displayRefreshHz')}") + f"viewport={r.get('viewportWidth')}x{r.get('viewportHeight')} x{r.get('viewCount')} refresh={r.get('displayRefreshHz')}" + + (" lock diagnostics build" if lock_mode else "")) if args.update: os.makedirs(base_dir, exist_ok=True) @@ -165,12 +215,21 @@ def main(): return 0 regressions = 0 + not_judged = 0 for scene in scenes: path = os.path.join(base_dir, f"{scene['id']}.json") s = scene["summary"] over, missed = scene_rates(s) head = (f"{scene['id']}: frames {s.get('frames',0)} p95 {s.get('p95FrameMs',0):.2f} p99 {s.get('p99FrameMs',0):.2f} " f"gpu {s.get('meanGPUExecutionMs',0):.2f} overBudget {over*100:.2f}% missed {missed*100:.2f}%") + if lock_mode: + now_locks = lock_metrics(s) + total = sum(v["calls"] for v in now_locks.values()) + waited = sum(v["waitMs"] for v in now_locks.values()) + head = f"{scene['id']}: frames {s.get('frames',0)} lock calls {total:.0f}/frame, wait {waited:.3f} ms/frame" + other_load = scene.get("otherProcessLoadCores", 0.0) + if other_load >= args.busy_cores: + head += f" [machine busy: other processes used {other_load:.1f} cores in the quietest run]" if not os.path.exists(path): print(f"{head} [no baseline]") continue @@ -183,17 +242,43 @@ def main(): bover, bmissed = scene_rates(b) print(head) + if lock_mode: + ref_locks = lock_metrics(b) + for name in sorted(set(now_locks) | set(ref_locks), key=lambda n: -now_locks.get(n, ref_locks.get(n))["calls"]): + now, ref = now_locks.get(name), ref_locks.get(name) + if ref is None: + print(f" {name:28s} {now['calls']:9.0f} calls/frame (new lock name, not in the baseline)") + continue + if now is None: + print(f" {name:28s} gone ({ref['calls']:.0f} calls/frame in the baseline)") + continue + delta = (now["calls"] - ref["calls"]) / ref["calls"] if ref["calls"] > 0 else 0.0 + flag = "REGRESSION" if delta > args.lock_call_tolerance else ("better" if delta < -args.lock_call_tolerance else "ok") + print(f" {name:28s} {now['calls']:9.0f} vs {ref['calls']:9.0f} calls/frame {delta*100:+7.1f}% {flag}") + regressions += flag == "REGRESSION" + moved = abs(now["waitMs"] - ref["waitMs"]) > args.lock_wait_slack_ms + wdelta = (now["waitMs"] - ref["waitMs"]) / ref["waitMs"] if ref["waitMs"] > 0 else (1.0 if now["waitMs"] > 0 else 0.0) + if moved or now["waitMs"] > args.lock_wait_slack_ms or ref["waitMs"] > args.lock_wait_slack_ms: + wflag = "REGRESSION" if wdelta > args.lock_wait_tolerance and moved else ("better" if wdelta < -args.lock_wait_tolerance and moved else "ok") + print(f" {' wait':28s} {now['waitMs']:9.3f} vs {ref['waitMs']:9.3f} ms/frame {wdelta*100:+7.1f}% {wflag}" + f" (contended {now['contended']:.0f} vs {ref['contended']:.0f} per frame)") + regressions += wflag == "REGRESSION" + continue + # With the GPU idle most of the frame its times follow the clock state, not the workload. gpu_busy = rate(b.get("meanGPUExecutionMs", 0.0), b.get("meanFrameMs", 0.0)) >= args.gpu_busy_fraction - def judge(label, now, ref, tolerance, unit="ms", relative=True, slack=0.0, informational=False): + machine_busy = other_load >= args.busy_cores + + def judge(label, now, ref, tolerance, unit="ms", relative=True, slack=0.0, informational=False, + reason="GPU mostly idle"): nonlocal regressions if relative: if ref <= 0: return delta = (now - ref) / ref if informational: - print(f" {label:28s} {now:9.3f} vs {ref:9.3f} {unit} {delta*100:+7.1f}% (info, GPU mostly idle)") + print(f" {label:28s} {now:9.3f} vs {ref:9.3f} {unit} {delta*100:+7.1f}% (info, {reason})") return moved = abs(now - ref) > slack flag = "REGRESSION" if delta > tolerance and moved else ("better" if delta < -tolerance and moved else "ok") @@ -201,24 +286,36 @@ def judge(label, now, ref, tolerance, unit="ms", relative=True, slack=0.0, infor else: delta = now - ref flag = "REGRESSION" if delta > tolerance else "ok" + if informational: + flag = f"(info, {reason})" print(f" {label:28s} {now*100:8.2f}% vs {ref*100:8.2f}% {delta*100:+6.2f}pt {flag}") if flag == "REGRESSION": regressions += 1 for key, label in FRAME_METRICS: - is_gpu = key == "minGPUExecutionMs" - judge(label, s.get(key, 0.0), b.get(key, 0.0), args.time_tolerance, - slack=args.gpu_slack_ms if is_gpu else 0.0, informational=is_gpu and not gpu_busy) + if key == "minGPUExecutionMs": + judge(label, s.get(key, 0.0), b.get(key, 0.0), args.time_tolerance, + slack=args.gpu_slack_ms, informational=not gpu_busy) + else: + judge(label, s.get(key, 0.0), b.get(key, 0.0), args.time_tolerance, + informational=machine_busy, reason="machine busy") for key, label in INFO_METRICS: now, ref = s.get(key, 0.0), b.get(key, 0.0) if ref > 0: print(f" {label:28s} {now:9.3f} vs {ref:9.3f} ms {(now-ref)/ref*100:+7.1f}% (info)") - judge("overBudgetRate", over, bover, args.rate_tolerance, relative=False) - judge("missedDeadlineRate", missed, bmissed, args.rate_tolerance, relative=False) + judge("overBudgetRate", over, bover, args.rate_tolerance, relative=False, + informational=machine_busy, reason="machine busy") + judge("missedDeadlineRate", missed, bmissed, args.rate_tolerance, relative=False, + informational=machine_busy, reason="machine busy") + not_judged += machine_busy tnow, tref = s.get("timingMeanMs", {}), b.get("timingMeanMs", {}) for field in TIMING_FIELDS: if field in tnow and field in tref and tref[field] >= 0.02: - judge(f"cpu {field}", tnow[field], tref[field], args.time_tolerance, slack=args.cpu_slack_ms) + if tref[field] >= args.cpu_floor_ms: + judge(f"cpu {field}", tnow[field], tref[field], args.time_tolerance, slack=args.cpu_slack_ms) + else: + delta = (tnow[field] - tref[field]) / tref[field] + print(f" {'cpu ' + field:28s} {tnow[field]:9.3f} vs {tref[field]:9.3f} ms {delta*100:+7.1f}% (info, under {args.cpu_floor_ms:g} ms)") pnow, pref = s.get("gpuPassMinMs", {}), b.get("gpuPassMinMs", {}) untimed = sorted(label for label in pref if label not in pnow and pref[label] >= 0.05) if untimed: @@ -230,6 +327,9 @@ def judge(label, now, ref, tolerance, unit="ms", relative=True, slack=0.0, infor if label in pnow and pref[label] >= 0.05: judge(f"gpu min {label[:20]}", pnow[label], pref[label], args.pass_tolerance, slack=args.pass_slack_ms, informational=not gpu_busy) + if not_judged: + print(f"frame pacing not judged in {not_judged} scene(s): other processes kept the machine busy; " + "run again on a quiet machine to judge it") if regressions: print(f"{regressions} regression(s)") return 1 diff --git a/scripts/perf/run_bench.sh b/scripts/perf/run_bench.sh index 7f53d632e..523f65176 100755 --- a/scripts/perf/run_bench.sh +++ b/scripts/perf/run_bench.sh @@ -8,7 +8,18 @@ # scripts/perf/run_bench.sh ios --device [options] # scripts/perf/run_bench.sh visionos --device [options] # +# Sessions (--session NAME) bundle the options for the three ways the benchmark is used: +# quick four scenes (cube, primitives-1k, animation-16, stadium), 10 s each, three repeats, +# compared against the baseline. About three minutes: the one to run for every change. +# locks the engine built with ENGINE_LOCK_DIAGNOSTICS, on primitives-1k and the three lock +# scenes (public API calls, loading, a second thread), two repeats, judged on lock calls +# and lock wait time per frame against the lock baseline. +# full every scene, three repeats, then the locks session. With --update-baseline it refreshes +# both baselines. +# An option given explicitly wins over what the session sets. +# # Options: +# --session NAME quick, locks or full (see above) # --scenes a,b,c scene ids (default: all) # --seconds N recorded seconds per scene (default: 15) # --warmup N warm-up seconds per scene (default: 3) @@ -21,8 +32,8 @@ # --xctrace TEMPLATE also record an Instruments trace, e.g. "Metal System Trace" (device runs) # --lock-diagnostics build the engine with ENGINE_LOCK_DIAGNOSTICS: every engine lock is counted # and timed, and each scene reports lock calls, contention, wait and hold -# time. Frame times of such a build are not comparable with a normal one, -# so the baseline comparison is skipped. +# time. Frame times of such a build are not comparable with a normal one; +# the run is compared against the lock baseline, on its lock numbers only. # --no-compare skip the baseline comparison # --update-baseline write this run as the new baseline for the device model # @@ -32,7 +43,7 @@ set -euo pipefail PLATFORM="${1:-}" -[ -n "$PLATFORM" ] || { sed -n '2,24p' "$0"; exit 2; } +[ -n "$PLATFORM" ] || { sed -n '2,/^set -euo/p' "$0" | sed '$d'; exit 2; } shift REPO="$(cd "$(dirname "$0")/../.." && pwd)" @@ -51,26 +62,59 @@ COMPARE=1 UPDATE_BASELINE=0 REPEAT=1 REFRESH="" +SESSION="" +SCENES_SET=0 +SECONDS_SET=0 +REPEAT_SET=0 while [ $# -gt 0 ]; do case "$1" in - --scenes) SCENES="$2"; shift 2 ;; - --seconds) SECONDS_PER_SCENE="$2"; shift 2 ;; + --session) SESSION="$2"; shift 2 ;; + --scenes) SCENES="$2"; SCENES_SET=1; shift 2 ;; + --seconds) SECONDS_PER_SCENE="$2"; SECONDS_SET=1; shift 2 ;; --warmup) WARMUP="$2"; shift 2 ;; --out) OUT_DIR="$2"; shift 2 ;; --label) LABEL="$2"; shift 2 ;; --config) CONFIG="$2"; shift 2 ;; --device) DEVICE="$2"; shift 2 ;; - --repeat) REPEAT="$2"; shift 2 ;; + --repeat) REPEAT="$2"; REPEAT_SET=1; shift 2 ;; --refresh) REFRESH="$2"; shift 2 ;; --xctrace) XCTRACE_TEMPLATE="$2"; shift 2 ;; - --lock-diagnostics) LOCK_DIAGNOSTICS=1; COMPARE=0; shift ;; + --lock-diagnostics) LOCK_DIAGNOSTICS=1; shift ;; --no-compare) COMPARE=0; shift ;; --update-baseline) UPDATE_BASELINE=1; shift ;; *) echo "unknown option $1"; exit 2 ;; esac done +case "$SESSION" in + "") ;; + quick) + [ "$SCENES_SET" = 1 ] || SCENES="cube,primitives-1k,animation-16,stadium" + [ "$SECONDS_SET" = 1 ] || SECONDS_PER_SCENE=10 + [ "$REPEAT_SET" = 1 ] || REPEAT=3 + ;; + locks) + LOCK_DIAGNOSTICS=1 + [ "$SCENES_SET" = 1 ] || SCENES="primitives-1k,locks-api,locks-loading,locks-threads" + [ "$SECONDS_SET" = 1 ] || SECONDS_PER_SCENE=10 + [ "$REPEAT_SET" = 1 ] || REPEAT=2 + ;; + full) + # Two passes with their own builds: every scene in a normal build, then the locks session. + COMMON=(--out "$OUT_DIR" --config "$CONFIG" --label "$LABEL") + [ -z "$DEVICE" ] || COMMON+=(--device "$DEVICE") + [ -z "$REFRESH" ] || COMMON+=(--refresh "$REFRESH") + [ "$UPDATE_BASELINE" = 0 ] || COMMON+=(--update-baseline) + [ "$COMPARE" = 1 ] || COMMON+=(--no-compare) + STATUS=0 + "$0" "$PLATFORM" --repeat "$([ "$REPEAT_SET" = 1 ] && echo "$REPEAT" || echo 3)" "${COMMON[@]}" || STATUS=$? + "$0" "$PLATFORM" --session locks "${COMMON[@]}" || STATUS=$? + exit "$STATUS" + ;; + *) echo "session must be quick, locks or full"; exit 2 ;; +esac + RUN_ID="$(date +%Y%m%d-%H%M%S)-$PLATFORM" DERIVED="$BENCH_DIR/.build/DerivedData" EXTRA_BUILD_SETTINGS=()