Added caching in the playerdata factory, refactored

LightlessSync/PlayerData/Factories/PlayerDataFactory.cs

@@ -8,6 +8,8 @@ using LightlessSync.PlayerData.Handlers;
 using LightlessSync.Services;
 using LightlessSync.Services.Mediator;
 using Microsoft.Extensions.Logging;
+using System.Collections.Concurrent;
+using System.Diagnostics;
 
 namespace LightlessSync.PlayerData.Factories;
 
@@ -23,9 +25,27 @@ public class PlayerDataFactory
     private readonly TransientResourceManager _transientResourceManager;
     private static readonly SemaphoreSlim _papParseLimiter = new(1, 1);
 
-    public PlayerDataFactory(ILogger<PlayerDataFactory> logger, DalamudUtilService dalamudUtil, IpcManager ipcManager,
+    // Transient resolved entries threshold
-        TransientResourceManager transientResourceManager, FileCacheManager fileReplacementFactory,
+    private const int _maxTransientResolvedEntries = 1000;
-        PerformanceCollectorService performanceCollector, XivDataAnalyzer modelAnalyzer, LightlessMediator lightlessMediator)
+
+    // Character build caches
+    private readonly ConcurrentDictionary<nint, Task<CharacterDataFragment>> _characterBuildInflight = new();
+    private readonly ConcurrentDictionary<nint, CacheEntry> _characterBuildCache = new();
+
+    // Time out thresholds
+    private static readonly TimeSpan _characterCacheTtl = TimeSpan.FromMilliseconds(750);
+    private static readonly TimeSpan _softReturnIfBusyAfter = TimeSpan.FromMilliseconds(250);
+    private static readonly TimeSpan _hardBuildTimeout = TimeSpan.FromSeconds(30);
+
+    public PlayerDataFactory(
+        ILogger<PlayerDataFactory> logger,
+        DalamudUtilService dalamudUtil,
+        IpcManager ipcManager,
+        TransientResourceManager transientResourceManager,
+        FileCacheManager fileReplacementFactory,
+        PerformanceCollectorService performanceCollector,
+        XivDataAnalyzer modelAnalyzer,
+        LightlessMediator lightlessMediator)
     {
         _logger = logger;
         _dalamudUtil = dalamudUtil;
@@ -37,13 +57,12 @@ public class PlayerDataFactory
         _lightlessMediator = lightlessMediator;
         _logger.LogTrace("Creating {this}", nameof(PlayerDataFactory));
     }
+    private sealed record CacheEntry(CharacterDataFragment Fragment, DateTime CreatedUtc);
 
     public async Task<CharacterDataFragment?> BuildCharacterData(GameObjectHandler playerRelatedObject, CancellationToken token)
     {
         if (!_ipcManager.Initialized)
-        {
             throw new InvalidOperationException("Penumbra or Glamourer is not connected");
-        }
 
         if (playerRelatedObject == null) return null;
 
@@ -68,16 +87,17 @@ public class PlayerDataFactory
 
         if (pointerIsZero)
         {
-            _logger.LogTrace("Pointer was zero for {objectKind}", playerRelatedObject.ObjectKind);
+            _logger.LogTrace("Pointer was zero for {objectKind}; couldn't build character", playerRelatedObject.ObjectKind);
             return null;
         }
 
         try
         {
-            return await _performanceCollector.LogPerformance(this, $"CreateCharacterData>{playerRelatedObject.ObjectKind}", async () =>
+            return await _performanceCollector.LogPerformance(
-            {
+                this,
-                return await CreateCharacterData(playerRelatedObject, token).ConfigureAwait(false);
+                $"CreateCharacterData>{playerRelatedObject.ObjectKind}",
-            }).ConfigureAwait(true);
+                async () => await CreateCharacterData(playerRelatedObject, token).ConfigureAwait(false)
+            ).ConfigureAwait(false);
         }
         catch (OperationCanceledException)
         {
@@ -93,17 +113,14 @@ public class PlayerDataFactory
     }
 
     private async Task<bool> CheckForNullDrawObject(IntPtr playerPointer)
-    {
+        => await _dalamudUtil.RunOnFrameworkThread(() => CheckForNullDrawObjectUnsafe(playerPointer)).ConfigureAwait(false);
-        return await _dalamudUtil.RunOnFrameworkThread(() => CheckForNullDrawObjectUnsafe(playerPointer)).ConfigureAwait(false);
-    }
 
-    private unsafe bool CheckForNullDrawObjectUnsafe(IntPtr playerPointer)
+    private unsafe static bool CheckForNullDrawObjectUnsafe(IntPtr playerPointer)
     {
         if (playerPointer == IntPtr.Zero)
             return true;
 
         var character = (Character*)playerPointer;
-
         if (character == null)
             return true;
 
@@ -114,111 +131,167 @@ public class PlayerDataFactory
         return gameObject->DrawObject == null;
     }
 
-    private async Task<CharacterDataFragment> CreateCharacterData(GameObjectHandler playerRelatedObject, CancellationToken ct)
+    private static bool IsCacheFresh(CacheEntry entry)
+        => (DateTime.UtcNow - entry.CreatedUtc) <= _characterCacheTtl;
+
+    private Task<CharacterDataFragment> CreateCharacterData(GameObjectHandler playerRelatedObject, CancellationToken ct)
+        => CreateCharacterDataCoalesced(playerRelatedObject, ct);
+
+    private async Task<CharacterDataFragment> CreateCharacterDataCoalesced(GameObjectHandler obj, CancellationToken ct)
+    {
+        var key = obj.Address;
+
+        if (_characterBuildCache.TryGetValue(key, out var cached) && IsCacheFresh(cached) && !_characterBuildInflight.ContainsKey(key))
+            return cached.Fragment;
+
+        var buildTask = _characterBuildInflight.GetOrAdd(key, _ => BuildAndCacheAsync(obj, key));
+
+        if (_characterBuildCache.TryGetValue(key, out cached))
+        {
+            var completed = await Task.WhenAny(buildTask, Task.Delay(_softReturnIfBusyAfter, ct)).ConfigureAwait(false);
+            if (completed != buildTask && (DateTime.UtcNow - cached.CreatedUtc) <= TimeSpan.FromSeconds(5))
+            {
+                return cached.Fragment;
+            }
+        }
+
+        return await WithCancellation(buildTask, ct).ConfigureAwait(false);
+    }
+
+    private async Task<CharacterDataFragment> BuildAndCacheAsync(GameObjectHandler obj, nint key)
+    {
+        try
+        {
+            using var cts = new CancellationTokenSource(_hardBuildTimeout);
+            var fragment = await CreateCharacterDataInternal(obj, cts.Token).ConfigureAwait(false);
+
+            _characterBuildCache[key] = new CacheEntry(fragment, DateTime.UtcNow);
+            PruneCharacterCacheIfNeeded();
+
+            return fragment;
+        }
+        finally
+        {
+            _characterBuildInflight.TryRemove(key, out _);
+        }
+    }
+
+    private void PruneCharacterCacheIfNeeded()
+    {
+        if (_characterBuildCache.Count < 2048) return;
+
+        var cutoff = DateTime.UtcNow - TimeSpan.FromSeconds(10);
+        foreach (var kv in _characterBuildCache)
+        {
+            if (kv.Value.CreatedUtc < cutoff)
+                _characterBuildCache.TryRemove(kv.Key, out _);
+        }
+    }
+
+    private static async Task<T> WithCancellation<T>(Task<T> task, CancellationToken ct)
+        => await task.WaitAsync(ct).ConfigureAwait(false);
+
+    private async Task<CharacterDataFragment> CreateCharacterDataInternal(GameObjectHandler playerRelatedObject, CancellationToken ct)
     {
         var objectKind = playerRelatedObject.ObjectKind;
         CharacterDataFragment fragment = objectKind == ObjectKind.Player ? new CharacterDataFragmentPlayer() : new();
 
-        _logger.LogDebug("Building character data for {obj}", playerRelatedObject);
         var logDebug = _logger.IsEnabled(LogLevel.Debug);
+        var sw = Stopwatch.StartNew();
 
-        await _dalamudUtil.WaitWhileCharacterIsDrawing(_logger, playerRelatedObject, Guid.NewGuid(), 30000, ct: ct).ConfigureAwait(false);
+        _logger.LogDebug("Building character data for {obj}", playerRelatedObject);
-        int totalWaitTime = 10000;
+
-        while (!await _dalamudUtil.IsObjectPresentAsync(await _dalamudUtil.CreateGameObjectAsync(playerRelatedObject.Address).ConfigureAwait(false)).ConfigureAwait(false) && totalWaitTime > 0)
+        await EnsureObjectPresentAsync(playerRelatedObject, ct).ConfigureAwait(false);
-        {
+        ct.ThrowIfCancellationRequested();
-            _logger.LogTrace("Character is null but it shouldn't be, waiting");
+
-            await Task.Delay(50, ct).ConfigureAwait(false);
+        var waitRecordingTask = _transientResourceManager.WaitForRecording(ct);
-            totalWaitTime -= 50;
+
-        }
+        await _dalamudUtil.WaitWhileCharacterIsDrawing(_logger, playerRelatedObject, Guid.NewGuid(), 30000, ct: ct)
+            .ConfigureAwait(false);
 
         ct.ThrowIfCancellationRequested();
 
-        DateTime start = DateTime.UtcNow;
+        if (await CheckForNullDrawObject(playerRelatedObject.Address).ConfigureAwait(false))
-
+            throw new InvalidOperationException("DrawObject became null during build (actor despawned)");
-        Dictionary<string, HashSet<string>>? resolvedPaths;
-
-        resolvedPaths = (await _ipcManager.Penumbra.GetCharacterData(_logger, playerRelatedObject).ConfigureAwait(false));
-        if (resolvedPaths == null) throw new InvalidOperationException("Penumbra returned null data");
-
-        ct.ThrowIfCancellationRequested();
-
-        var fileReplacementsTask = Task.Run(() =>
-        {
-            var replacements = new HashSet<FileReplacement>(
-                resolvedPaths.Select(c => new FileReplacement([.. c.Value], c.Key)),
-                FileReplacementComparer.Instance)
-                .Where(p => p.HasFileReplacement)
-                .ToHashSet();
-
-            replacements.RemoveWhere(c => c.GamePaths.Any(g =>
-                !CacheMonitor.AllowedFileExtensions.Any(e =>
-                    g.EndsWith(e, StringComparison.OrdinalIgnoreCase))));
-
-            return replacements;
-        }, ct);
-
-        ct.ThrowIfCancellationRequested();
 
+        Task<string> getGlamourerData = _ipcManager.Glamourer.GetCharacterCustomizationAsync(playerRelatedObject.Address);
+        Task<string?> getCustomizeData = _ipcManager.CustomizePlus.GetScaleAsync(playerRelatedObject.Address);
+        Task<string?>? getMoodlesData = null;
         Task<string>? getHeelsOffset = null;
-        Task<string>? getGlamourerData = null;
-        Task<string?>? getCustomizeData = null;
         Task<string>? getHonorificTitle = null;
-        Task<string>? getMoodlesData = null;
 
         if (objectKind == ObjectKind.Player)
         {
             getHeelsOffset = _ipcManager.Heels.GetOffsetAsync();
-            getGlamourerData = _ipcManager.Glamourer.GetCharacterCustomizationAsync(playerRelatedObject.Address);
-            getCustomizeData = _ipcManager.CustomizePlus.GetScaleAsync(playerRelatedObject.Address);
             getHonorificTitle = _ipcManager.Honorific.GetTitle();
             getMoodlesData = _ipcManager.Moodles.GetStatusAsync(playerRelatedObject.Address);
         }
-        else
-        {
-            getGlamourerData = _ipcManager.Glamourer.GetCharacterCustomizationAsync(playerRelatedObject.Address);
-            getCustomizeData = _ipcManager.CustomizePlus.GetScaleAsync(playerRelatedObject.Address);
-        }
 
-        fragment.FileReplacements = await fileReplacementsTask.ConfigureAwait(false);
+        var resolvedPaths = await _ipcManager.Penumbra.GetCharacterData(_logger, playerRelatedObject).ConfigureAwait(false) ?? throw new InvalidOperationException("Penumbra returned null data; couldn't proceed with character");
+        ct.ThrowIfCancellationRequested();
+
+        var staticBuildTask = Task.Run(() => BuildStaticReplacements(resolvedPaths), ct);
+
+        fragment.FileReplacements = await staticBuildTask.ConfigureAwait(false);
 
         if (logDebug)
         {
             _logger.LogDebug("== Static Replacements ==");
-            foreach (var replacement in fragment.FileReplacements.Where(i => i.HasFileReplacement).OrderBy(i => i.GamePaths.First(), StringComparer.OrdinalIgnoreCase))
+            foreach (var replacement in fragment.FileReplacements
+                         .Where(i => i.HasFileReplacement)
+                         .OrderBy(i => i.GamePaths.First(), StringComparer.OrdinalIgnoreCase))
             {
                 _logger.LogDebug("=> {repl}", replacement);
                 ct.ThrowIfCancellationRequested();
             }
         }
-        else
-        {
-            foreach (var replacement in fragment.FileReplacements.Where(i => i.HasFileReplacement))
-            {
-                ct.ThrowIfCancellationRequested();
-            }
-        }
 
-        var staticReplacements = fragment.FileReplacements.ToHashSet();
+        var staticReplacements = new HashSet<FileReplacement>(fragment.FileReplacements, FileReplacementComparer.Instance);
 
-        Task<(IReadOnlyDictionary<string, string[]> ResolvedPaths, HashSet<FileReplacement>? ClearedReplacements)> transientTask = ProcessTransientDataAsync(
+        var transientTask = ResolveTransientReplacementsAsync(
-            objectKind,
             playerRelatedObject,
+            objectKind,
             staticReplacements,
+            waitRecordingTask,
             ct);
 
+        fragment.GlamourerString = await getGlamourerData.ConfigureAwait(false);
+        _logger.LogDebug("Glamourer is now: {data}", fragment.GlamourerString);
+
+        var customizeScale = await getCustomizeData.ConfigureAwait(false);
+        fragment.CustomizePlusScale = customizeScale ?? string.Empty;
+        _logger.LogDebug("Customize is now: {data}", fragment.CustomizePlusScale);
+
+        if (objectKind == ObjectKind.Player)
+        {
+            CharacterDataFragmentPlayer? playerFragment = fragment as CharacterDataFragmentPlayer ?? throw new InvalidOperationException("Failed to cast CharacterDataFragment to Player variant");
+
+            playerFragment.ManipulationString = _ipcManager.Penumbra.GetMetaManipulations();
+            playerFragment.HonorificData = await getHonorificTitle!.ConfigureAwait(false);
+            _logger.LogDebug("Honorific is now: {data}", playerFragment!.HonorificData);
+
+            playerFragment.PetNamesData = _ipcManager.PetNames.GetLocalNames();
+            _logger.LogDebug("Pet Nicknames is now: {petnames}", playerFragment!.PetNamesData);
+
+            playerFragment.HeelsData = await getHeelsOffset!.ConfigureAwait(false);
+            _logger.LogDebug("Heels is now: {heels}", playerFragment!.HeelsData);
+
+            playerFragment.MoodlesData = (await getMoodlesData!.ConfigureAwait(false)) ?? string.Empty;
+            _logger.LogDebug("Moodles is now: {moodles}", playerFragment!.MoodlesData);
+        }
+
         ct.ThrowIfCancellationRequested();
 
         var (resolvedTransientPaths, clearedForPet) = await transientTask.ConfigureAwait(false);
-
         if (clearedForPet != null)
-        {
             fragment.FileReplacements.Clear();
-        }
 
         if (logDebug)
         {
             _logger.LogDebug("== Transient Replacements ==");
-            foreach (var replacement in resolvedTransientPaths.Select(c => new FileReplacement([.. c.Value], c.Key)).OrderBy(f => f.ResolvedPath, StringComparer.Ordinal))
+            foreach (var replacement in resolvedTransientPaths
+                         .Select(c => new FileReplacement([.. c.Value], c.Key))
+                         .OrderBy(f => f.ResolvedPath, StringComparer.Ordinal))
             {
                 _logger.LogDebug("=> {repl}", replacement);
                 fragment.FileReplacements.Add(replacement);
@@ -227,40 +300,16 @@ public class PlayerDataFactory
         else
         {
             foreach (var replacement in resolvedTransientPaths.Select(c => new FileReplacement([.. c.Value], c.Key)))
-            {
                 fragment.FileReplacements.Add(replacement);
-            }
         }
 
         _transientResourceManager.CleanUpSemiTransientResources(objectKind, [.. fragment.FileReplacements]);
 
-        ct.ThrowIfCancellationRequested();
+        fragment.FileReplacements = new HashSet<FileReplacement>(
-
+            fragment.FileReplacements
-        fragment.FileReplacements = new HashSet<FileReplacement>(fragment.FileReplacements.Where(v => v.HasFileReplacement).OrderBy(v => v.ResolvedPath, StringComparer.Ordinal), FileReplacementComparer.Instance);
+                .Where(v => v.HasFileReplacement)
-
+                .OrderBy(v => v.ResolvedPath, StringComparer.Ordinal),
-        fragment.GlamourerString = await getGlamourerData.ConfigureAwait(false);
+            FileReplacementComparer.Instance);
-        _logger.LogDebug("Glamourer is now: {data}", fragment.GlamourerString);
-        var customizeScale = await getCustomizeData.ConfigureAwait(false);
-        fragment.CustomizePlusScale = customizeScale ?? string.Empty;
-        _logger.LogDebug("Customize is now: {data}", fragment.CustomizePlusScale);
-
-        if (objectKind == ObjectKind.Player)
-        {
-            var playerFragment = (fragment as CharacterDataFragmentPlayer)!;
-            playerFragment.ManipulationString = _ipcManager.Penumbra.GetMetaManipulations();
-
-            playerFragment!.HonorificData = await getHonorificTitle!.ConfigureAwait(false);
-            _logger.LogDebug("Honorific is now: {data}", playerFragment!.HonorificData);
-
-            playerFragment!.HeelsData = await getHeelsOffset!.ConfigureAwait(false);
-            _logger.LogDebug("Heels is now: {heels}", playerFragment!.HeelsData);
-
-            playerFragment!.MoodlesData = await getMoodlesData!.ConfigureAwait(false) ?? string.Empty;
-            _logger.LogDebug("Moodles is now: {moodles}", playerFragment!.MoodlesData);
-
-            playerFragment!.PetNamesData = _ipcManager.PetNames.GetLocalNames();
-            _logger.LogDebug("Pet Nicknames is now: {petnames}", playerFragment!.PetNamesData);
-        }
 
         ct.ThrowIfCancellationRequested();
 
@@ -269,7 +318,7 @@ public class PlayerDataFactory
 
         await Task.Run(() =>
         {
-            var computedPaths = _fileCacheManager.GetFileCachesByPaths(toCompute.Select(c => c.ResolvedPath).ToArray());
+            var computedPaths = _fileCacheManager.GetFileCachesByPaths([.. toCompute.Select(c => c.ResolvedPath)]);
             foreach (var file in toCompute)
             {
                 ct.ThrowIfCancellationRequested();
@@ -279,9 +328,7 @@ public class PlayerDataFactory
 
         var removed = fragment.FileReplacements.RemoveWhere(f => !f.IsFileSwap && string.IsNullOrEmpty(f.Hash));
         if (removed > 0)
-        {
             _logger.LogDebug("Removed {amount} of invalid files", removed);
-        }
 
         ct.ThrowIfCancellationRequested();
 
@@ -299,21 +346,16 @@ public class PlayerDataFactory
                     .RunOnFrameworkThread(() => _modelAnalyzer.GetSkeletonBoneIndices(playerRelatedObject))
                     .ConfigureAwait(false);
             }
-        }
 
-        if (objectKind == ObjectKind.Player)
-        {
             try
             {
 #if DEBUG
                 if (hasPapFiles && boneIndices != null)
-                {
                     _modelAnalyzer.DumpLocalSkeletonIndices(playerRelatedObject);
-                }
 #endif
                 if (hasPapFiles)
                 {
-                    await VerifyPlayerAnimationBones(boneIndices, (fragment as CharacterDataFragmentPlayer)!, ct)
+                    await VerifyPlayerAnimationBones(boneIndices, (CharacterDataFragmentPlayer)fragment, ct)
                         .ConfigureAwait(false);
                 }
             }
@@ -328,11 +370,94 @@ public class PlayerDataFactory
             }
         }
 
-        _logger.LogInformation("Building character data for {obj} took {time}ms", objectKind, TimeSpan.FromTicks(DateTime.UtcNow.Ticks - start.Ticks).TotalMilliseconds);
+        _logger.LogInformation("Building character data for {obj} took {time}ms",
+            objectKind, sw.Elapsed.TotalMilliseconds);
 
         return fragment;
     }
 
+    private async Task EnsureObjectPresentAsync(GameObjectHandler handler, CancellationToken ct)
+    {
+        var remaining = 10000;
+        while (remaining > 0)
+        {
+            ct.ThrowIfCancellationRequested();
+
+            var obj = await _dalamudUtil.CreateGameObjectAsync(handler.Address).ConfigureAwait(false);
+            if (await _dalamudUtil.IsObjectPresentAsync(obj).ConfigureAwait(false))
+                return;
+
+            _logger.LogTrace("Character is null but it shouldn't be, waiting");
+            await Task.Delay(50, ct).ConfigureAwait(false);
+            remaining -= 50;
+        }
+    }
+
+    private static HashSet<FileReplacement> BuildStaticReplacements(Dictionary<string, HashSet<string>> resolvedPaths)
+    {
+        var set = new HashSet<FileReplacement>(FileReplacementComparer.Instance);
+
+        foreach (var kvp in resolvedPaths)
+        {
+            var fr = new FileReplacement([.. kvp.Value], kvp.Key);
+            if (!fr.HasFileReplacement) continue;
+
+            var allAllowed = fr.GamePaths.All(g =>
+                CacheMonitor.AllowedFileExtensions.Any(e => g.EndsWith(e, StringComparison.OrdinalIgnoreCase)));
+
+            if (!allAllowed) continue;
+
+            set.Add(fr);
+        }
+
+        return set;
+    }
+
+    private async Task<(IReadOnlyDictionary<string, string[]> ResolvedPaths, HashSet<FileReplacement>? ClearedReplacements)>
+        ResolveTransientReplacementsAsync(
+            GameObjectHandler obj,
+            ObjectKind objectKind,
+            HashSet<FileReplacement> staticReplacements,
+            Task waitRecordingTask,
+            CancellationToken ct)
+    {
+        await waitRecordingTask.ConfigureAwait(false);
+
+        HashSet<FileReplacement>? clearedReplacements = null;
+
+        if (objectKind == ObjectKind.Pet)
+        {
+            foreach (var item in staticReplacements.Where(i => i.HasFileReplacement).SelectMany(p => p.GamePaths))
+            {
+                if (_transientResourceManager.AddTransientResource(objectKind, item))
+                    _logger.LogDebug("Marking static {item} for Pet as transient", item);
+            }
+
+            _logger.LogTrace("Clearing {count} Static Replacements for Pet", staticReplacements.Count);
+            clearedReplacements = staticReplacements;
+        }
+
+        ct.ThrowIfCancellationRequested();
+
+        _transientResourceManager.ClearTransientPaths(objectKind, [.. staticReplacements.SelectMany(c => c.GamePaths)]);
+
+        var transientPaths = ManageSemiTransientData(objectKind);
+        if (transientPaths.Count == 0)
+            return (new Dictionary<string, string[]>(StringComparer.Ordinal), clearedReplacements);
+
+        var resolved = await GetFileReplacementsFromPaths(obj, transientPaths, new HashSet<string>(StringComparer.Ordinal))
+            .ConfigureAwait(false);
+
+        if (_maxTransientResolvedEntries > 0 && resolved.Count > _maxTransientResolvedEntries)
+        {
+            _logger.LogWarning("Transient entries ({resolved}) are above the threshold {max}; Please consider disable some mods (VFX have heavy load) to reduce transient load",
+                resolved.Count,
+                _maxTransientResolvedEntries);
+        }
+
+        return (resolved, clearedReplacements);
+    }
+
     private async Task VerifyPlayerAnimationBones(
         Dictionary<string, List<ushort>>? playerBoneIndices,
         CharacterDataFragmentPlayer fragment,
@@ -347,12 +472,13 @@ public class PlayerDataFactory
         {
             if (indices == null || indices.Count == 0)
                 continue;
+
             var key = XivDataAnalyzer.CanonicalizeSkeletonKey(rawLocalKey);
             if (string.IsNullOrEmpty(key))
                 continue;
 
             if (!playerBoneSets.TryGetValue(key, out var set))
-                playerBoneSets[key] = set = new HashSet<ushort>();
+                playerBoneSets[key] = set = [];
 
             foreach (var idx in indices)
                 set.Add(idx);
@@ -361,18 +487,6 @@ public class PlayerDataFactory
         if (playerBoneSets.Count == 0)
             return;
 
-        if (_logger.IsEnabled(LogLevel.Debug))
-        {
-            foreach (var kvp in playerBoneSets)
-            {
-                _logger.LogDebug(
-                    "Found local skeleton bucket '{bucket}' ({count} indices, max {max})",
-                    kvp.Key,
-                    kvp.Value.Count,
-                    kvp.Value.Count > 0 ? kvp.Value.Max() : 0);
-            }
-        }
-
         var papFiles = fragment.FileReplacements
             .Where(f => !f.IsFileSwap && f.GamePaths.First().EndsWith("pap", StringComparison.OrdinalIgnoreCase))
             .ToList();
@@ -414,7 +528,6 @@ public class PlayerDataFactory
             ct.ThrowIfCancellationRequested();
 
             var hash = group.Key;
-
             Dictionary<string, List<ushort>>? papSkeletonIndices;
 
             await _papParseLimiter.WaitAsync(ct).ConfigureAwait(false);
@@ -432,10 +545,7 @@ public class PlayerDataFactory
                 continue;
 
             if (ShouldIgnorePap(papSkeletonIndices))
-            {
-                _logger.LogTrace("All indices of PAP hash {hash} are <= 105, ignoring", hash);
                 continue;
-            }
 
             bool invalid = false;
             string? reason = null;
@@ -480,7 +590,6 @@ public class PlayerDataFactory
 
             foreach (var file in group.ToList())
             {
-                _logger.LogDebug("Removing {file} from sent file replacements and transient data", file.ResolvedPath);
                 fragment.FileReplacements.Remove(file);
 
                 foreach (var gamePath in file.GamePaths)
@@ -500,75 +609,30 @@ public class PlayerDataFactory
         }
     }
 
-    private async Task<(IReadOnlyDictionary<string, string[]> ResolvedPaths, HashSet<FileReplacement>? ClearedReplacements)> ProcessTransientDataAsync(
+    private async Task<IReadOnlyDictionary<string, string[]>> GetFileReplacementsFromPaths(
-    ObjectKind objectKind,
+        GameObjectHandler handler,
-    GameObjectHandler playerRelatedObject,
+        HashSet<string> forwardResolve,
-    HashSet<FileReplacement> staticReplacements,
+        HashSet<string> reverseResolve)
-    CancellationToken ct)
-    {
-        await _transientResourceManager.WaitForRecording(ct).ConfigureAwait(false);
-
-        HashSet<FileReplacement>? clearedReplacements = null;
-
-        var gamePaths = staticReplacements
-            .Where(i => i.HasFileReplacement)
-            .SelectMany(p => p.GamePaths)
-            .ToList();
-
-        if (objectKind == ObjectKind.Pet)
-        {
-            foreach (var item in gamePaths)
-            {
-                if (_transientResourceManager.AddTransientResource(objectKind, item))
-                {
-                    _logger.LogDebug("Marking static {item} for Pet as transient", item);
-                }
-            }
-
-            _logger.LogTrace("Clearing {count} Static Replacements for Pet", staticReplacements.Count);
-            clearedReplacements = staticReplacements;
-        }
-
-        ct.ThrowIfCancellationRequested();
-
-        _transientResourceManager.ClearTransientPaths(objectKind, gamePaths);
-
-        var transientPaths = ManageSemiTransientData(objectKind);
-        IReadOnlyDictionary<string, string[]> resolved = await GetFileReplacementsFromPaths(
-            playerRelatedObject,
-            transientPaths,
-            new HashSet<string>(StringComparer.Ordinal)).ConfigureAwait(false);
-
-        return (resolved, clearedReplacements);
-    }
-
-
-    private async Task<IReadOnlyDictionary<string, string[]>> GetFileReplacementsFromPaths(GameObjectHandler handler, HashSet<string> forwardResolve, HashSet<string> reverseResolve)
     {
         var forwardPaths = forwardResolve.ToArray();
         var reversePaths = reverseResolve.ToArray();
         Dictionary<string, List<string>> resolvedPaths = new(StringComparer.Ordinal);
+
         if (handler.ObjectKind != ObjectKind.Player)
         {
             var (objectIndex, forwardResolved, reverseResolved) = await _dalamudUtil.RunOnFrameworkThread(() =>
             {
                 var idx = handler.GetGameObject()?.ObjectIndex;
                 if (!idx.HasValue)
-                {
                     return ((int?)null, Array.Empty<string>(), Array.Empty<string[]>());
-                }
 
                 var resolvedForward = new string[forwardPaths.Length];
                 for (int i = 0; i < forwardPaths.Length; i++)
-                {
                     resolvedForward[i] = _ipcManager.Penumbra.ResolveGameObjectPath(forwardPaths[i], idx.Value);
-                }
 
                 var resolvedReverse = new string[reversePaths.Length][];
                 for (int i = 0; i < reversePaths.Length; i++)
-                {
                     resolvedReverse[i] = _ipcManager.Penumbra.ReverseResolveGameObjectPath(reversePaths[i], idx.Value);
-                }
 
                 return (idx, resolvedForward, resolvedReverse);
             }).ConfigureAwait(false);
@@ -579,31 +643,21 @@ public class PlayerDataFactory
                 {
                     var filePath = forwardResolved[i]?.ToLowerInvariant();
                     if (string.IsNullOrEmpty(filePath))
-                    {
                         continue;
-                    }
 
                     if (resolvedPaths.TryGetValue(filePath, out var list))
-                    {
                         list.Add(forwardPaths[i].ToLowerInvariant());
-                    }
                     else
-                    {
                         resolvedPaths[filePath] = [forwardPaths[i].ToLowerInvariant()];
-                    }
                 }
 
                 for (int i = 0; i < reversePaths.Length; i++)
                 {
                     var filePath = reversePaths[i].ToLowerInvariant();
                     if (resolvedPaths.TryGetValue(filePath, out var list))
-                    {
                         list.AddRange(reverseResolved[i].Select(c => c.ToLowerInvariant()));
-                    }
                     else
-                    {
+                        resolvedPaths[filePath] = [.. reverseResolved[i].Select(c => c.ToLowerInvariant()).ToList()];
-                        resolvedPaths[filePath] = new List<string>(reverseResolved[i].Select(c => c.ToLowerInvariant()).ToList());
-                    }
                 }
 
                 return resolvedPaths.ToDictionary(k => k.Key, k => k.Value.ToArray(), StringComparer.OrdinalIgnoreCase).AsReadOnly();
@@ -611,30 +665,23 @@ public class PlayerDataFactory
         }
 
         var (forward, reverse) = await _ipcManager.Penumbra.ResolvePathsAsync(forwardPaths, reversePaths).ConfigureAwait(false);
+
         for (int i = 0; i < forwardPaths.Length; i++)
         {
             var filePath = forward[i].ToLowerInvariant();
             if (resolvedPaths.TryGetValue(filePath, out var list))
-            {
                 list.Add(forwardPaths[i].ToLowerInvariant());
-            }
             else
-            {
                 resolvedPaths[filePath] = [forwardPaths[i].ToLowerInvariant()];
-            }
         }
 
         for (int i = 0; i < reversePaths.Length; i++)
         {
             var filePath = reversePaths[i].ToLowerInvariant();
             if (resolvedPaths.TryGetValue(filePath, out var list))
-            {
                 list.AddRange(reverse[i].Select(c => c.ToLowerInvariant()));
-            }
             else
-            {
                 resolvedPaths[filePath] = new List<string>(reverse[i].Select(c => c.ToLowerInvariant()).ToList());
-            }
         }
 
         return resolvedPaths.ToDictionary(k => k.Key, k => k.Value.ToArray(), StringComparer.OrdinalIgnoreCase).AsReadOnly();
@@ -645,11 +692,29 @@ public class PlayerDataFactory
         _transientResourceManager.PersistTransientResources(objectKind);
 
         HashSet<string> pathsToResolve = new(StringComparer.Ordinal);
-        foreach (var path in _transientResourceManager.GetSemiTransientResources(objectKind).Where(path => !string.IsNullOrEmpty(path)))
+
+        int scanned = 0, skippedEmpty = 0, skippedVfx = 0;
+
+        foreach (var path in _transientResourceManager.GetSemiTransientResources(objectKind))
         {
+            scanned++;
+
+            if (string.IsNullOrEmpty(path))
+            {
+                skippedEmpty++;
+                continue;
+            }
+
             pathsToResolve.Add(path);
         }
 
+        if (_logger.IsEnabled(LogLevel.Debug))
+        {
+            _logger.LogDebug(
+                "ManageSemiTransientData({kind}): scanned={scanned}, added={added}, skippedEmpty={skippedEmpty}, skippedVfx={skippedVfx}",
+                objectKind, scanned, pathsToResolve.Count, skippedEmpty, skippedVfx);
+        }
+
         return pathsToResolve;
     }
 }

LightlessSync/Services/DalamudUtilService.cs

@@ -22,8 +22,10 @@ using LightlessSync.Utils;
 using Lumina.Excel.Sheets;
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
+using System.Diagnostics;
 using System.Numerics;
 using System.Runtime.CompilerServices;
+using System.Runtime.InteropServices;
 using System.Text;
 using BattleNpcSubKind = FFXIVClientStructs.FFXIV.Client.Game.Object.BattleNpcSubKind;
 using DalamudObjectKind = Dalamud.Game.ClientState.Objects.Enums.ObjectKind;
@@ -843,31 +845,41 @@ public class DalamudUtilService : IHostedService, IMediatorSubscriber
         return Task.CompletedTask;
     }
 
-    public async Task WaitWhileCharacterIsDrawing(ILogger logger, GameObjectHandler handler, Guid redrawId, int timeOut = 5000, CancellationToken? ct = null)
+    public async Task WaitWhileCharacterIsDrawing(
+        ILogger logger,
+        GameObjectHandler handler,
+        Guid redrawId,
+        int timeOut = 5000,
+        CancellationToken? ct = null)
     {
         if (!_clientState.IsLoggedIn) return;
 
-        if (ct == null)
+        var token = ct ?? CancellationToken.None;
-            ct = CancellationToken.None;
 
         const int tick = 250; 
-        int curWaitTime = 0;
+        const int initialSettle = 50;
+
+        var sw = Stopwatch.StartNew();
+
         try
         {
             logger.LogTrace("[{redrawId}] Starting wait for {handler} to draw", redrawId, handler);
-            await Task.Delay(tick, ct.Value).ConfigureAwait(true);
-            curWaitTime += tick;
 
-            while ((!ct.Value.IsCancellationRequested)
+            await Task.Delay(initialSettle, token).ConfigureAwait(false);
-                   && curWaitTime < timeOut
+
-                   && await handler.IsBeingDrawnRunOnFrameworkAsync().ConfigureAwait(false)) // 0b100000000000 is "still rendering" or something
+            while (!token.IsCancellationRequested
+                   && sw.ElapsedMilliseconds < timeOut
+                   && await handler.IsBeingDrawnRunOnFrameworkAsync().ConfigureAwait(false))
             {
                 logger.LogTrace("[{redrawId}] Waiting for {handler} to finish drawing", redrawId, handler);
-                curWaitTime += tick;
+                await Task.Delay(tick, token).ConfigureAwait(false);
-                await Task.Delay(tick, ct.Value).ConfigureAwait(true);
             }
 
-            logger.LogTrace("[{redrawId}] Finished drawing after {curWaitTime}ms", redrawId, curWaitTime);
+            logger.LogTrace("[{redrawId}] Finished drawing after {ms}ms", redrawId, sw.ElapsedMilliseconds);
+        }
+        catch (OperationCanceledException)
+        {
+            // ignore
         }
         catch (AccessViolationException ex)
         {