From 08daee3258ee371c3646f07fe112c0ac95e6bf6a Mon Sep 17 00:00:00 2001 From: phranck Date: Thu, 5 Feb 2026 14:40:58 +0100 Subject: [PATCH] Feat: render cache debug tooling with per-frame stats and review fixes Add RenderCache.Stats for cache performance tracking: - Hit/miss/store/clear counters with hit rate calculation - Per-frame delta via Stats.delta(since:) for meaningful frame-level logging - TUIKIT_DEBUG_RENDER=1 env var enables stderr logging (zero cost when off) - logDebug uses @autoclosure to avoid string allocation in production Review fixes applied: - F1: logFrameStats() now logs per-frame delta, not cumulative totals - F2: clearAll() no longer reads entries.count unconditionally - F3: Remove unnecessary Sendable from Stats (main-thread only type) - F5: reset() now also clears stats and frame snapshot - F7: Move EnvironmentSnapshot to RenderLoop.swift (private, where it belongs) - F8: Build snapshot from EnvironmentValues, not from ThemeManager directly --- Sources/TUIkit/App/RenderLoop.swift | 35 ++++- Sources/TUIkit/Rendering/RenderCache.swift | 147 +++++++++++++++++--- Tests/TUIkitTests/RenderCacheTests.swift | 150 +++++++++++++++++++++ 3 files changed, 307 insertions(+), 25 deletions(-) diff --git a/Sources/TUIkit/App/RenderLoop.swift b/Sources/TUIkit/App/RenderLoop.swift index 5b8caab..c336ca4 100644 --- a/Sources/TUIkit/App/RenderLoop.swift +++ b/Sources/TUIkit/App/RenderLoop.swift @@ -5,6 +5,31 @@ // CC BY-NC-SA 4.0 assembly, and status bar output. // +// MARK: - Environment Snapshot + +/// A snapshot of environment values that affect rendered output. +/// +/// Used by ``RenderLoop`` to detect environment changes (theme, appearance) +/// between frames. When the snapshot differs from the previous frame, the +/// render cache is cleared so ``EquatableView``-cached subtrees re-render +/// with the updated values. +/// +/// Only tracks values that affect visual output — reference-type infrastructure +/// services (`FocusManager`, `ThemeManager`) are excluded. +private struct EnvironmentSnapshot: Equatable { + /// The active palette identifier. + let paletteID: String + + /// The active appearance identifier. + let appearanceID: String + + /// Creates a snapshot from fully-built environment values. + init(from environment: EnvironmentValues) { + self.paletteID = environment.palette.id + self.appearanceID = environment.appearance.id + } +} + // MARK: - Render Loop /// Manages the full rendering pipeline for each frame. @@ -154,7 +179,7 @@ extension RenderLoop { // Create render context with environment let environment = buildEnvironment() - invalidateCacheIfEnvironmentChanged() + invalidateCacheIfEnvironmentChanged(environment: environment) var context = RenderContext( availableWidth: terminalWidth, @@ -251,6 +276,7 @@ extension RenderLoop { tuiContext.lifecycle.endRenderPass() tuiContext.stateStorage.endRenderPass() tuiContext.renderCache.removeInactive() + tuiContext.renderCache.logFrameStats() } /// Invalidates the diff cache, forcing a full repaint on the next render. @@ -291,11 +317,8 @@ private extension RenderLoop { /// /// This runs once per frame (two string comparisons) and ensures developers /// never need to manually invalidate the cache after theme changes. - func invalidateCacheIfEnvironmentChanged() { - let currentSnapshot = EnvironmentSnapshot( - paletteID: paletteManager.current.id, - appearanceID: appearanceManager.current.id - ) + func invalidateCacheIfEnvironmentChanged(environment: EnvironmentValues) { + let currentSnapshot = EnvironmentSnapshot(from: environment) if let lastSnapshot = lastEnvironmentSnapshot, lastSnapshot != currentSnapshot { tuiContext.renderCache.clearAll() } diff --git a/Sources/TUIkit/Rendering/RenderCache.swift b/Sources/TUIkit/Rendering/RenderCache.swift index 43e8f71..6a3852b 100644 --- a/Sources/TUIkit/Rendering/RenderCache.swift +++ b/Sources/TUIkit/Rendering/RenderCache.swift @@ -4,21 +4,10 @@ // Created by LAYERED.work // CC BY-NC-SA 4.0 +import Foundation + // MARK: - Render Cache -/// A snapshot of environment values that affect rendered output. -/// -/// Used by ``RenderLoop`` to detect environment changes (theme, appearance) -/// that require cache invalidation. Only tracks values that affect visual -/// output — reference-type infrastructure services are excluded. -struct EnvironmentSnapshot: Equatable { - /// The active palette identifier. - let paletteID: String - - /// The active appearance identifier. - let appearanceID: String -} - /// Caches rendered ``FrameBuffer`` results for views that opt into subtree memoization. /// /// `RenderCache` is Phase 5 of TUIKit's render pipeline optimization. It stores @@ -49,12 +38,55 @@ struct EnvironmentSnapshot: Equatable { /// render pass are removed in ``removeInactive()``, matching /// ``StateStorage``'s existing GC pattern. /// +/// ## Debug Logging +/// +/// Set the environment variable `TUIKIT_DEBUG_RENDER=1` to enable per-frame +/// cache statistics logging to stderr. This logs hit/miss counts, cache size, +/// and individual identity lookups to help diagnose memoization effectiveness. +/// /// ## Thread Safety /// /// `RenderCache` is accessed only from the main thread (TUIKit's single-threaded /// event loop). No locking is required. final class RenderCache: @unchecked Sendable { + /// Aggregated cache performance statistics. + /// + /// Tracks hit/miss/store/clear counts. Use ``stats`` for cumulative + /// totals, or ``frameStats`` (after ``logFrameStats()``) for the + /// delta since the last ``beginRenderPass()``. + struct Stats: Equatable { + /// Number of successful cache lookups (view and size matched). + var hits: Int = 0 + + /// Number of failed cache lookups (identity missing, view changed, or size changed). + var misses: Int = 0 + + /// Number of entries stored (including overwrites). + var stores: Int = 0 + + /// Number of times ``clearAll()`` was called. + var clears: Int = 0 + + /// The total number of lookups (hits + misses). + var lookups: Int { hits + misses } + + /// The cache hit rate as a value between 0 and 1, or 0 if no lookups occurred. + var hitRate: Double { + lookups > 0 ? Double(hits) / Double(lookups) : 0 + } + + /// Returns the per-element difference between this snapshot and an earlier one. + func delta(since earlier: Self) -> Self { + Self( + hits: hits - earlier.hits, + misses: misses - earlier.misses, + stores: stores - earlier.stores, + clears: clears - earlier.clears + ) + } + } + /// A cached rendering result for a single view identity. struct CacheEntry { /// The type-erased view value at the time of caching. @@ -78,6 +110,17 @@ final class RenderCache: @unchecked Sendable { /// Identities seen during the current render pass (for garbage collection). private var activeIdentities: Set = [] + /// Cumulative cache performance statistics. + private(set) var stats = Stats() + + /// Stats snapshot taken at the start of each render pass (for per-frame deltas). + private var statsAtFrameStart = Stats() + + /// Whether debug logging is enabled via the `TUIKIT_DEBUG_RENDER` environment variable. + static let debugEnabled: Bool = { + ProcessInfo.processInfo.environment["TUIKIT_DEBUG_RENDER"] == "1" + }() + /// Creates an empty render cache. init() {} @@ -109,11 +152,29 @@ extension RenderCache { contextWidth: Int, contextHeight: Int ) -> FrameBuffer? { - guard let entry = entries[identity] else { return nil } - guard let oldView = entry.viewSnapshot as? V else { return nil } + guard let entry = entries[identity] else { + stats.misses += 1 + logDebug("MISS (no entry) \(identity.path)") + return nil + } + guard let oldView = entry.viewSnapshot as? V else { + stats.misses += 1 + logDebug("MISS (type mismatch) \(identity.path)") + return nil + } guard entry.contextWidth == contextWidth, - entry.contextHeight == contextHeight else { return nil } - guard oldView == view else { return nil } + entry.contextHeight == contextHeight else { + stats.misses += 1 + logDebug("MISS (size changed) \(identity.path)") + return nil + } + guard oldView == view else { + stats.misses += 1 + logDebug("MISS (view changed) \(identity.path)") + return nil + } + stats.hits += 1 + logDebug("HIT \(identity.path)") return entry.buffer } @@ -134,12 +195,14 @@ extension RenderCache { contextWidth: Int, contextHeight: Int ) { + stats.stores += 1 entries[identity] = CacheEntry( viewSnapshot: view, buffer: buffer, contextWidth: contextWidth, contextHeight: contextHeight ) + logDebug("STORE \(identity.path)") } /// Marks an identity as active during the current render pass. @@ -152,9 +215,11 @@ extension RenderCache { activeIdentities.insert(identity) } - /// Begins a new render pass by clearing the active identity set. + /// Begins a new render pass by clearing the active identity set + /// and snapshotting the current stats for per-frame delta calculation. func beginRenderPass() { activeIdentities.removeAll(keepingCapacity: true) + statsAtFrameStart = stats } /// Removes cache entries for views no longer in the tree. @@ -172,13 +237,57 @@ extension RenderCache { /// /// Called when any `@State` value changes, because state changes /// can propagate to any subtree through bindings or environment. + /// Also called by ``RenderLoop`` when environment values change + /// (theme, appearance). func clearAll() { + stats.clears += 1 + logDebug("CLEAR ALL (\(entries.count) entries)") entries.removeAll(keepingCapacity: true) } - /// Removes all cached entries and resets GC state. + /// Removes all cached entries, resets GC state, and clears statistics. func reset() { entries.removeAll() activeIdentities.removeAll() + stats = Stats() + statsAtFrameStart = Stats() + } + + /// Resets the cumulative statistics counters to zero. + func resetStats() { + stats = Stats() + } + + /// Logs a per-frame summary to stderr if debug logging is enabled. + /// + /// Call this at the end of each render pass (after ``removeInactive()``) + /// to emit a one-line summary showing **this frame's** cache activity + /// (delta since ``beginRenderPass()``) plus the current entry count. + func logFrameStats() { + guard Self.debugEnabled else { return } + let frame = stats.delta(since: statsAtFrameStart) + let rate = frame.lookups > 0 + ? String(format: "%.0f%%", frame.hitRate * 100) + : "n/a" + logDebug( + "FRAME — hits: \(frame.hits), misses: \(frame.misses), " + + "stores: \(frame.stores), clears: \(frame.clears), " + + "entries: \(entries.count), hit rate: \(rate)" + ) + } +} + +// MARK: - Private Helpers + +private extension RenderCache { + /// Writes a debug message to stderr when `TUIKIT_DEBUG_RENDER=1` is set. + /// + /// Uses stderr so debug output never interferes with the terminal UI + /// rendered on stdout. Redirect with `2>render.log` to capture. + func logDebug(_ message: @autoclosure () -> String) { + guard Self.debugEnabled else { return } + FileHandle.standardError.write( + Data("[RenderCache] \(message())\n".utf8) + ) } } diff --git a/Tests/TUIkitTests/RenderCacheTests.swift b/Tests/TUIkitTests/RenderCacheTests.swift index a0704bf..5dd2f99 100644 --- a/Tests/TUIkitTests/RenderCacheTests.swift +++ b/Tests/TUIkitTests/RenderCacheTests.swift @@ -152,4 +152,154 @@ struct RenderCacheTests { let result = cache.lookup(identity: identity, view: "42", contextWidth: 80, contextHeight: 24) #expect(result == nil) } + + // MARK: - Stats + + @Test("Stats start at zero") + func statsInitiallyZero() { + let cache = RenderCache() + #expect(cache.stats == RenderCache.Stats()) + #expect(cache.stats.hits == 0) + #expect(cache.stats.misses == 0) + #expect(cache.stats.stores == 0) + #expect(cache.stats.clears == 0) + } + + @Test("Cache hit increments hits counter") + func statsCountHits() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + + #expect(cache.stats.hits == 2) + #expect(cache.stats.misses == 0) + } + + @Test("Cache miss increments misses counter") + func statsCountMisses() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + + // Miss: different view value + _ = cache.lookup(identity: identity, view: "B", contextWidth: 80, contextHeight: 24) + // Miss: unknown identity + _ = cache.lookup(identity: ViewIdentity(path: "Root/Other"), view: "A", contextWidth: 80, contextHeight: 24) + // Miss: different size + _ = cache.lookup(identity: identity, view: "A", contextWidth: 120, contextHeight: 24) + + #expect(cache.stats.misses == 3) + #expect(cache.stats.hits == 0) + } + + @Test("Store increments stores counter") + func statsCountStores() { + let cache = RenderCache() + cache.store(identity: ViewIdentity(path: "A"), view: 1, buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + cache.store(identity: ViewIdentity(path: "B"), view: 2, buffer: FrameBuffer(text: "b"), contextWidth: 80, contextHeight: 24) + // Overwrite existing entry + cache.store(identity: ViewIdentity(path: "A"), view: 3, buffer: FrameBuffer(text: "c"), contextWidth: 80, contextHeight: 24) + + #expect(cache.stats.stores == 3) + } + + @Test("clearAll increments clears counter") + func statsCountClears() { + let cache = RenderCache() + cache.store(identity: ViewIdentity(path: "A"), view: 1, buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + + cache.clearAll() + cache.clearAll() + + #expect(cache.stats.clears == 2) + } + + @Test("Stats accumulate across multiple operations") + func statsAccumulateAcrossOperations() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + + // 1 store + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + // 1 hit + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + // 1 miss (view changed) + _ = cache.lookup(identity: identity, view: "B", contextWidth: 80, contextHeight: 24) + // 1 clear + cache.clearAll() + // 1 miss (cache empty) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + + #expect(cache.stats.hits == 1) + #expect(cache.stats.misses == 2) + #expect(cache.stats.stores == 1) + #expect(cache.stats.clears == 1) + #expect(cache.stats.lookups == 3) + } + + @Test("Hit rate is calculated correctly") + func statsHitRate() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + + // 3 hits + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + // 1 miss + _ = cache.lookup(identity: identity, view: "B", contextWidth: 80, contextHeight: 24) + + #expect(cache.stats.hitRate == 0.75) + } + + @Test("Hit rate is zero when no lookups occurred") + func statsHitRateZeroWithoutLookups() { + let cache = RenderCache() + #expect(cache.stats.hitRate == 0) + } + + @Test("resetStats clears all counters") + func resetStatsClearsCounters() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + cache.clearAll() + + #expect(cache.stats.hits > 0) + cache.resetStats() + #expect(cache.stats == RenderCache.Stats()) + } + + @Test("reset() also clears statistics") + func resetClearsStats() { + let cache = RenderCache() + let identity = ViewIdentity(path: "Root/View") + cache.store(identity: identity, view: "A", buffer: FrameBuffer(text: "a"), contextWidth: 80, contextHeight: 24) + _ = cache.lookup(identity: identity, view: "A", contextWidth: 80, contextHeight: 24) + cache.clearAll() + + #expect(cache.stats.hits > 0) + cache.reset() + #expect(cache.stats == RenderCache.Stats()) + #expect(cache.isEmpty) + } + + @Test("Stats delta computes per-frame difference") + func statsDelta() { + let earlier = RenderCache.Stats(hits: 10, misses: 5, stores: 8, clears: 2) + let current = RenderCache.Stats(hits: 13, misses: 7, stores: 9, clears: 3) + + let delta = current.delta(since: earlier) + + #expect(delta.hits == 3) + #expect(delta.misses == 2) + #expect(delta.stores == 1) + #expect(delta.clears == 1) + #expect(delta.lookups == 5) + } }