From 44450b24b492f72e0a34510a4c50ed676e7156b6 Mon Sep 17 00:00:00 2001 From: rootdarkarchon Date: Sun, 19 Feb 2023 16:11:40 +0100 Subject: [PATCH] add performance logging on demand, fix minion issues --- MareSynchronos/Export/MareCharaFileManager.cs | 2 +- .../Factories/CharacterDataFactory.cs | 68 ++++--- .../Factories/GameObjectHandlerFactory.cs | 7 +- .../FileCache/PeriodicFileScanner.cs | 23 ++- .../Managers/CacheCreationService.cs | 24 +-- MareSynchronos/Managers/CachedPlayer.cs | 124 ++++++------- MareSynchronos/Managers/IpcManager.cs | 44 ++--- .../Managers/ServerConfigurationManager.cs | 2 +- .../Managers/TransientResourceManager.cs | 25 ++- .../ConfigurationMigrator.cs | 2 +- .../ConfigurationServiceBase.cs | 2 +- .../Configurations/MareConfig.cs | 1 + .../Configurations/Obsolete/Configuration.cs | 8 - MareSynchronos/MarePlugin.cs | 13 +- MareSynchronos/Mediator/MareMediator.cs | 34 ++-- MareSynchronos/Mediator/Messages.cs | 4 +- MareSynchronos/Models/GameObjectHandler.cs | 98 +++++----- MareSynchronos/Plugin.cs | 7 +- MareSynchronos/UI/CompactUI.cs | 2 +- MareSynchronos/UI/SettingsUi.cs | 31 +++- MareSynchronos/UI/UIShared.cs | 27 +-- MareSynchronos/Utils/DalamudLogger.cs | 19 +- MareSynchronos/Utils/DalamudUtil.cs | 39 ++-- MareSynchronos/Utils/PerformanceCollector.cs | 168 ++++++++++++++++++ MareSynchronos/Utils/RollingList.cs | 46 +++++ .../WebAPI/ApIController.Functions.Files.cs | 24 ++- .../WebAPI/ApIController.Functions.Users.cs | 2 +- .../ApiController.Functions.Callbacks.cs | 2 +- MareSynchronos/WebAPI/ApiController.cs | 26 ++- 29 files changed, 580 insertions(+), 294 deletions(-) create mode 100644 MareSynchronos/Utils/PerformanceCollector.cs create mode 100644 MareSynchronos/Utils/RollingList.cs diff --git a/MareSynchronos/Export/MareCharaFileManager.cs b/MareSynchronos/Export/MareCharaFileManager.cs index 6f1b146..bea1bc9 100644 --- a/MareSynchronos/Export/MareCharaFileManager.cs +++ b/MareSynchronos/Export/MareCharaFileManager.cs @@ -131,7 +131,7 @@ public class MareCharaFileManager _ipcManager.PenumbraSetTemporaryMods(_logger, applicationId, charaTarget.Name.TextValue, extractedFiles.Union(fileSwaps).ToDictionary(d => d.Key, d => d.Value, StringComparer.Ordinal), LoadedCharaFile.CharaFileData.ManipulationData); - using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Player, () => charaTarget.Address, false); + using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Player, () => charaTarget.Address, isWatched: false); await _ipcManager.GlamourerApplyAll(_logger, tempHandler, LoadedCharaFile.CharaFileData.GlamourerData, applicationId, disposeCts.Token).ConfigureAwait(false); _dalamudUtil.WaitWhileGposeCharacterIsDrawing(charaTarget.Address, 30000); _ipcManager.PenumbraRemoveTemporaryCollection(_logger, applicationId, charaTarget.Name.TextValue); diff --git a/MareSynchronos/Factories/CharacterDataFactory.cs b/MareSynchronos/Factories/CharacterDataFactory.cs index e35e655..7a6bb6f 100644 --- a/MareSynchronos/Factories/CharacterDataFactory.cs +++ b/MareSynchronos/Factories/CharacterDataFactory.cs @@ -14,6 +14,7 @@ using MareSynchronos.FileCache; using MareSynchronos.Mediator; using System.Collections.Concurrent; using Microsoft.Extensions.Logging; +using System.Globalization; namespace MareSynchronos.Factories; @@ -23,16 +24,19 @@ public class CharacterDataFactory : MediatorSubscriberBase private readonly IpcManager _ipcManager; private readonly TransientResourceManager _transientResourceManager; private readonly FileCacheManager _fileCacheManager; - private ConcurrentQueue> _processingQueue = new(); + private readonly PerformanceCollector _performanceCollector; + private readonly ConcurrentQueue> _processingQueue = new(); public CharacterDataFactory(ILogger logger, DalamudUtil dalamudUtil, IpcManager ipcManager, - TransientResourceManager transientResourceManager, FileCacheManager fileReplacementFactory, MareMediator mediator) : base(logger, mediator) + TransientResourceManager transientResourceManager, FileCacheManager fileReplacementFactory, MareMediator mediator, + PerformanceCollector performanceCollector) : base(logger, mediator) { _logger.LogTrace("Creating " + nameof(CharacterDataFactory)); _dalamudUtil = dalamudUtil; _ipcManager = ipcManager; _transientResourceManager = transientResourceManager; _fileCacheManager = fileReplacementFactory; + _performanceCollector = performanceCollector; Mediator.Subscribe(this, (_) => { while (_processingQueue.TryDequeue(out var result)) @@ -54,6 +58,8 @@ public class CharacterDataFactory : MediatorSubscriberBase throw new InvalidOperationException("Penumbra is not connected"); } + if (playerRelatedObject == null) return previousData; + bool pointerIsZero = true; try { @@ -65,17 +71,17 @@ public class CharacterDataFactory : MediatorSubscriberBase catch { pointerIsZero = true; - _logger.LogDebug("NullRef for " + playerRelatedObject.ObjectKind); + _logger.LogDebug("NullRef for {object}", playerRelatedObject); } } catch (Exception ex) { - _logger.LogWarning("Could not create data for " + playerRelatedObject.ObjectKind, ex); + _logger.LogWarning(ex, "Could not create data for {object}", playerRelatedObject); } if (pointerIsZero) { - _logger.LogTrace("Pointer was zero for " + playerRelatedObject.ObjectKind); + _logger.LogTrace("Pointer was zero for {objectKind}", playerRelatedObject.ObjectKind); previousData.FileReplacements.Remove(playerRelatedObject.ObjectKind); previousData.GlamourerString.Remove(playerRelatedObject.ObjectKind); return previousData; @@ -87,17 +93,20 @@ public class CharacterDataFactory : MediatorSubscriberBase try { _processingQueue.Clear(); - return await CreateCharacterData(previousData, playerRelatedObject, token).ConfigureAwait(false); + return await _performanceCollector.LogPerformance(this, "CreateCharacterData>" + playerRelatedObject.ObjectKind, async () => + { + return await CreateCharacterData(previousData, playerRelatedObject, token).ConfigureAwait(false); + }).ConfigureAwait(true); } catch (OperationCanceledException) { _processingQueue.Clear(); - _logger.LogDebug("Cancelled creating Character data"); + _logger.LogDebug("Cancelled creating Character data for {object}", playerRelatedObject); throw; } catch (Exception e) { - _logger.LogWarning("Failed to create " + playerRelatedObject.ObjectKind + " data", e); + _logger.LogWarning(e, "Failed to create {object} data", playerRelatedObject); } previousData.FileReplacements = previousFileReplacements; @@ -110,7 +119,7 @@ public class CharacterDataFactory : MediatorSubscriberBase var objectKind = playerRelatedObject.ObjectKind; var charaPointer = playerRelatedObject.Address; - _logger.LogDebug("Building character data for " + objectKind); + _logger.LogDebug("Building character data for {obj}", playerRelatedObject); if (!previousData.FileReplacements.ContainsKey(objectKind)) { @@ -156,7 +165,7 @@ public class CharacterDataFactory : MediatorSubscriberBase _logger.LogDebug("== Static Replacements =="); foreach (var replacement in previousData.FileReplacements[objectKind].Where(i => i.HasFileReplacement).OrderBy(i => i.GamePaths.First(), StringComparer.OrdinalIgnoreCase)) { - _logger.LogDebug(replacement.ToString()); + _logger.LogDebug("=> {repl}", replacement); } // if it's pet then it's summoner, if it's summoner we actually want to keep all filereplacements alive at all times @@ -169,7 +178,7 @@ public class CharacterDataFactory : MediatorSubscriberBase } } - _logger.LogDebug("Handling transient update for " + objectKind); + _logger.LogDebug("Handling transient update for {obj}", playerRelatedObject); // remove all potentially gathered paths from the transient resource manager that are resolved through static resolving _transientResourceManager.ClearTransientPaths(charaPointer, previousData.FileReplacements[objectKind].SelectMany(c => c.GamePaths).ToList()); @@ -181,7 +190,7 @@ public class CharacterDataFactory : MediatorSubscriberBase _logger.LogDebug("== Transient Replacements =="); foreach (var replacement in resolvedTransientPaths.Select(c => new FileReplacement(c.Value, c.Key, _fileCacheManager)).OrderBy(f => f.ResolvedPath, StringComparer.Ordinal)) { - _logger.LogDebug(replacement.ToString()); + _logger.LogDebug("=> {repl}", replacement); previousData.FileReplacements[objectKind].Add(replacement); } @@ -195,7 +204,8 @@ public class CharacterDataFactory : MediatorSubscriberBase } st.Stop(); - _logger.LogInformation("Building character data for " + objectKind + " took " + st.ElapsedMilliseconds + "ms"); + _logger.LogInformation("Building character data for {obj} took {time}ms", objectKind, st.ElapsedTicks / 60.0d); + return previousData; } @@ -237,7 +247,7 @@ public class CharacterDataFactory : MediatorSubscriberBase foreach (var item in _transientResourceManager.GetTransientResources((IntPtr)weaponObject)) { - _logger.LogTrace("Found transient weapon resource: " + item); + _logger.LogTrace("Found transient weapon resource: {item}", item); forwardResolve.Add(item); } @@ -249,7 +259,7 @@ public class CharacterDataFactory : MediatorSubscriberBase foreach (var item in _transientResourceManager.GetTransientResources((IntPtr)offHandWeapon)) { - _logger.LogTrace("Found transient offhand weapon resource: " + item); + _logger.LogTrace("Found transient offhand weapon resource: {item}", item); forwardResolve.Add(item); } } @@ -292,7 +302,7 @@ public class CharacterDataFactory : MediatorSubscriberBase _logger.LogWarning("Could not get model data"); return; } - _logger.LogTrace("Checking File Replacement for Model " + mdlPath); + _logger.LogTrace("Checking File Replacement for Model {path}", mdlPath); reverseResolve.Add(mdlPath); @@ -319,7 +329,7 @@ public class CharacterDataFactory : MediatorSubscriberBase return; } - _logger.LogTrace("Checking File Replacement for Material " + fileName); + _logger.LogTrace("Checking File Replacement for Material {file}", fileName); var mtrlPath = fileName.Split("|")[2]; reverseResolve.Add(mtrlPath); @@ -332,14 +342,14 @@ public class CharacterDataFactory : MediatorSubscriberBase { texPath = new ByteString(mtrlResourceHandle->TexString(resIdx)).ToString(); } - catch + catch (Exception e) { - _logger.LogWarning("Could not get Texture data for Material " + fileName); + _logger.LogWarning(e, "Could not get Texture data for Material {file}", fileName); } if (string.IsNullOrEmpty(texPath)) continue; - _logger.LogTrace("Checking File Replacement for Texture " + texPath); + _logger.LogTrace("Checking File Replacement for Texture {file}", texPath); AddReplacementsFromTexture(texPath, forwardResolve, reverseResolve); } @@ -347,12 +357,12 @@ public class CharacterDataFactory : MediatorSubscriberBase try { var shpkPath = "shader/sm5/shpk/" + new ByteString(mtrlResourceHandle->ShpkString).ToString(); - _logger.LogTrace("Checking File Replacement for Shader " + shpkPath); + _logger.LogTrace("Checking File Replacement for Shader {path}", shpkPath); forwardResolve.Add(shpkPath); } - catch + catch (Exception ex) { - _logger.LogTrace("Could not find shpk for Material " + fileName); + _logger.LogWarning(ex, "Could not find shpk for Material {path}", fileName); } } @@ -360,7 +370,7 @@ public class CharacterDataFactory : MediatorSubscriberBase { if (string.IsNullOrEmpty(texPath)) return; - _logger.LogTrace("Checking file Replacement for texture " + texPath); + _logger.LogTrace("Checking file Replacement for texture {path}", texPath); if (doNotReverseResolve) forwardResolve.Add(texPath); @@ -378,7 +388,7 @@ public class CharacterDataFactory : MediatorSubscriberBase private void AddReplacementSkeleton(ushort raceSexId, HashSet forwardResolve) { - string raceSexIdString = raceSexId.ToString("0000"); + string raceSexIdString = raceSexId.ToString("0000", CultureInfo.InvariantCulture); string skeletonPath = $"chara/human/c{raceSexIdString}/skeleton/base/b0001/skl_c{raceSexIdString}b0001.sklb"; forwardResolve.Add(skeletonPath); @@ -402,10 +412,10 @@ public class CharacterDataFactory : MediatorSubscriberBase var forwardPaths = forwardResolve.ToArray(); var reversePaths = reverseResolve.ToArray(); Dictionary> resolvedPaths = new(StringComparer.Ordinal); - var result = _ipcManager.PenumbraResolvePaths(forwardPaths, reversePaths); + var (forward, reverse) = _ipcManager.PenumbraResolvePaths(forwardPaths, reversePaths); for (int i = 0; i < forwardPaths.Length; i++) { - var filePath = result.forward[i].ToLowerInvariant(); + var filePath = forward[i].ToLowerInvariant(); if (resolvedPaths.TryGetValue(filePath, out var list)) { list.Add(forwardPaths[i].ToLowerInvariant()); @@ -421,11 +431,11 @@ public class CharacterDataFactory : MediatorSubscriberBase var filePath = reversePaths[i].ToLowerInvariant(); if (resolvedPaths.TryGetValue(filePath, out var list)) { - list.AddRange(result.reverse[i].Select(c => c.ToLowerInvariant())); + list.AddRange(reverse[i].Select(c => c.ToLowerInvariant())); } else { - resolvedPaths[filePath] = new List(result.reverse[i].Select(c => c.ToLowerInvariant()).ToList()); + resolvedPaths[filePath] = new List(reverse[i].Select(c => c.ToLowerInvariant()).ToList()); } } diff --git a/MareSynchronos/Factories/GameObjectHandlerFactory.cs b/MareSynchronos/Factories/GameObjectHandlerFactory.cs index e165652..31e6f51 100644 --- a/MareSynchronos/Factories/GameObjectHandlerFactory.cs +++ b/MareSynchronos/Factories/GameObjectHandlerFactory.cs @@ -1,6 +1,7 @@ using MareSynchronos.API.Data.Enum; using MareSynchronos.Mediator; using MareSynchronos.Models; +using MareSynchronos.Utils; using Microsoft.Extensions.Logging; namespace MareSynchronos.Factories; @@ -9,15 +10,17 @@ public class GameObjectHandlerFactory { private readonly ILoggerFactory _loggerFactory; private readonly MareMediator _mediator; + private readonly PerformanceCollector _performanceCollector; - public GameObjectHandlerFactory(ILoggerFactory loggerFactory, MareMediator mediator) + public GameObjectHandlerFactory(ILoggerFactory loggerFactory, MareMediator mediator, PerformanceCollector performanceCollector) { _loggerFactory = loggerFactory; _mediator = mediator; + _performanceCollector = performanceCollector; } public GameObjectHandler Create(ObjectKind objectKind, Func getAddress, bool isWatched) { - return new GameObjectHandler(_loggerFactory.CreateLogger(), _mediator, objectKind, getAddress, isWatched); + return new GameObjectHandler(_loggerFactory.CreateLogger(), _performanceCollector, _mediator, objectKind, getAddress, isWatched); } } \ No newline at end of file diff --git a/MareSynchronos/FileCache/PeriodicFileScanner.cs b/MareSynchronos/FileCache/PeriodicFileScanner.cs index ce760f0..58a4b5e 100644 --- a/MareSynchronos/FileCache/PeriodicFileScanner.cs +++ b/MareSynchronos/FileCache/PeriodicFileScanner.cs @@ -1,7 +1,9 @@ using System.Collections.Concurrent; +using System.Diagnostics; using MareSynchronos.Managers; using MareSynchronos.MareConfiguration; using MareSynchronos.Mediator; +using MareSynchronos.Utils; using Microsoft.Extensions.Logging; namespace MareSynchronos.FileCache; @@ -11,18 +13,19 @@ public class PeriodicFileScanner : MediatorSubscriberBase, IDisposable private readonly IpcManager _ipcManager; private readonly MareConfigService _configService; private readonly FileCacheManager _fileDbManager; + private readonly PerformanceCollector _performanceCollector; private CancellationTokenSource? _scanCancellationTokenSource; private Task? _fileScannerTask = null; public ConcurrentDictionary haltScanLocks = new(StringComparer.Ordinal); public PeriodicFileScanner(ILogger logger, IpcManager ipcManager, MareConfigService configService, - FileCacheManager fileDbManager, MareMediator mediator) : base(logger, mediator) + FileCacheManager fileDbManager, MareMediator mediator, PerformanceCollector performanceCollector) : base(logger, mediator) { _logger.LogTrace("Creating " + nameof(PeriodicFileScanner)); _ipcManager = ipcManager; _configService = configService; _fileDbManager = fileDbManager; - + _performanceCollector = performanceCollector; Mediator.Subscribe(this, (_) => StartScan()); Mediator.Subscribe(this, (msg) => HaltScan(((HaltScanMessage)msg).Source)); Mediator.Subscribe(this, (msg) => ResumeScan(((ResumeScanMessage)msg).Source)); @@ -104,7 +107,7 @@ public class PeriodicFileScanner : MediatorSubscriberBase, IDisposable isForced = false; TotalFiles = 0; _currentFileProgress = 0; - PeriodicFileScan(token); + _performanceCollector.LogPerformance(this, "PeriodicFileScan", () => PeriodicFileScan(token)); TotalFiles = 0; _currentFileProgress = 0; } @@ -204,20 +207,18 @@ public class PeriodicFileScanner : MediatorSubscriberBase, IDisposable scannedFiles[validatedCacheResult.Item2.ResolvedFilepath] = true; if (validatedCacheResult.Item1 == FileState.RequireUpdate) { - _logger.LogTrace("To update: " + validatedCacheResult.Item2.ResolvedFilepath); + _logger.LogTrace("To update: {path}", validatedCacheResult.Item2.ResolvedFilepath); entitiesToUpdate.Add(validatedCacheResult.Item2); } else if (validatedCacheResult.Item1 == FileState.RequireDeletion) { - _logger.LogTrace("To delete: " + validatedCacheResult.Item2.ResolvedFilepath); + _logger.LogTrace("To delete: {path}", validatedCacheResult.Item2.ResolvedFilepath); entitiesToRemove.Add(validatedCacheResult.Item2); } } catch (Exception ex) { - _logger.LogWarning("Failed validating " + cache.ResolvedFilepath); - _logger.LogWarning(ex.Message); - _logger.LogWarning(ex.StackTrace); + _logger.LogWarning(ex, "Failed validating {path}", cache.ResolvedFilepath); } Interlocked.Increment(ref _currentFileProgress); @@ -239,7 +240,7 @@ public class PeriodicFileScanner : MediatorSubscriberBase, IDisposable } catch (Exception ex) { - _logger.LogWarning("Error during enumerating FileCaches: " + ex.Message); + _logger.LogWarning(ex, "Error during enumerating FileCaches"); } Task.WaitAll(dbTasks); @@ -288,9 +289,7 @@ public class PeriodicFileScanner : MediatorSubscriberBase, IDisposable } catch (Exception ex) { - _logger.LogWarning("Failed adding " + c.Key); - _logger.LogWarning(ex.Message); - _logger.LogWarning(ex.StackTrace); + _logger.LogWarning(ex, "Failed adding {file}", c.Key); } Interlocked.Increment(ref _currentFileProgress); diff --git a/MareSynchronos/Managers/CacheCreationService.cs b/MareSynchronos/Managers/CacheCreationService.cs index 78c9c15..d5bbf34 100644 --- a/MareSynchronos/Managers/CacheCreationService.cs +++ b/MareSynchronos/Managers/CacheCreationService.cs @@ -23,14 +23,6 @@ public class CacheCreationService : MediatorSubscriberBase, IDisposable { _characterDataFactory = characterDataFactory; - _playerRelatedObjects.AddRange(new List() - { - new(Mediator, ObjectKind.Player, () => dalamudUtil.PlayerPointer), - new(Mediator, ObjectKind.MinionOrMount, () => (IntPtr)((Character*)dalamudUtil.PlayerPointer)->CompanionObject), - new(Mediator, ObjectKind.Pet, () => dalamudUtil.GetPet()), - new(Mediator, ObjectKind.Companion, () => dalamudUtil.GetCompanion()), - }); - Mediator.Subscribe(this, (msg) => { var actualMsg = (CreateCacheForObjectMessage)msg; @@ -39,10 +31,10 @@ public class CacheCreationService : MediatorSubscriberBase, IDisposable _playerRelatedObjects.AddRange(new List() { - gameObjectHandlerFactory.Create(ObjectKind.Player, () => dalamudUtil.PlayerPointer, true), - gameObjectHandlerFactory.Create(ObjectKind.MinionOrMount, () => (IntPtr)((Character*)dalamudUtil.PlayerPointer)->CompanionObject, true), - gameObjectHandlerFactory.Create(ObjectKind.Pet, () => dalamudUtil.GetPet(), true), - gameObjectHandlerFactory.Create(ObjectKind.Companion, () => dalamudUtil.GetCompanion(), true), + gameObjectHandlerFactory.Create(ObjectKind.Player, () => dalamudUtil.PlayerPointer, isWatched: true), + gameObjectHandlerFactory.Create(ObjectKind.MinionOrMount, () => dalamudUtil.GetMinionOrMount(), isWatched: true), + gameObjectHandlerFactory.Create(ObjectKind.Pet, () => dalamudUtil.GetPet(), isWatched: true), + gameObjectHandlerFactory.Create(ObjectKind.Companion, () => dalamudUtil.GetCompanion(), isWatched: true), }); Mediator.Subscribe(this, (msg) => @@ -55,7 +47,6 @@ public class CacheCreationService : MediatorSubscriberBase, IDisposable Mediator.Publish(new CharacterDataCreatedMessage(_lastCreatedData)); }); }); - Mediator.Subscribe(this, (msg) => UpdatePointers()); Mediator.Subscribe(this, (msg) => ProcessCacheCreation()); Mediator.Subscribe(this, (msg) => CustomizePlusChanged((CustomizePlusMessage)msg)); Mediator.Subscribe(this, (msg) => HeelsOffsetChanged((HeelsOffsetMessage)msg)); @@ -100,11 +91,6 @@ public class CacheCreationService : MediatorSubscriberBase, IDisposable } } - private void UpdatePointers() - { - Mediator.Publish(new PlayerRelatedObjectPointerUpdateMessage(_playerRelatedObjects.Select(f => f.Address).ToArray())); - } - private void ProcessCacheCreation() { if (_cachesToCreate.Any() && (_cacheCreationTask?.IsCompleted ?? true)) @@ -123,7 +109,7 @@ public class CacheCreationService : MediatorSubscriberBase, IDisposable } catch (Exception ex) { - _logger.LogCritical("Error during Cache Creation Processing", ex); + _logger.LogCritical(ex, "Error during Cache Creation Processing"); } finally { diff --git a/MareSynchronos/Managers/CachedPlayer.cs b/MareSynchronos/Managers/CachedPlayer.cs index bc6a762..95f8e3f 100644 --- a/MareSynchronos/Managers/CachedPlayer.cs +++ b/MareSynchronos/Managers/CachedPlayer.cs @@ -45,10 +45,10 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable public void ApplyCharacterData(API.Data.CharacterData characterData, OptionalPluginWarning warning, bool forced = false) { - _logger.LogDebug("Received data for " + this); + _logger.LogDebug("Received data for {player}", this); - _logger.LogDebug("Checking for files to download for player " + PlayerName); - _logger.LogDebug("Hash for data is " + characterData.DataHash.Value + ", current cache hash is " + _cachedData.DataHash.Value); + _logger.LogDebug("Checking for files to download for player {name}", this); + _logger.LogDebug("Hash for data is {newHash}, current cache hash is {oldHash}", characterData.DataHash.Value, _cachedData.DataHash.Value); if (!_ipcManager.CheckPenumbraApi()) return; if (!_ipcManager.CheckGlamourerApi()) return; @@ -86,7 +86,9 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable if (hasNewButNotOldFileReplacements || hasOldButNotNewFileReplacements || hasNewButNotOldGlamourerData || hasOldButNotNewGlamourerData) { - _logger.LogDebug($"Updating {objectKind} (Some new data arrived: {hasNewButNotOldFileReplacements} {hasOldButNotNewFileReplacements} {hasNewButNotOldGlamourerData} {hasOldButNotNewGlamourerData})"); + _logger.LogDebug("Updating {object} (Some new data arrived: NewButNotOldFiles:{hasNewButNotOldFileReplacements}," + + " OldButNotNewFiles:{hasOldButNotNewFileReplacements}, NewButNotOldGlam:{hasNewButNotOldGlamourerData}, OldButNotNewGlam:{hasOldButNotNewGlamourerData})", + this, hasNewButNotOldFileReplacements, hasOldButNotNewFileReplacements, hasOldButNotNewGlamourerData, hasNewButNotOldGlamourerData); charaDataToUpdate[objectKind].Add(PlayerChanges.Mods); } @@ -95,7 +97,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable bool listsAreEqual = Enumerable.SequenceEqual(oldData.FileReplacements[objectKind], newData.FileReplacements[objectKind], FileReplacementDataComparer.Instance); if (!listsAreEqual || forced) { - _logger.LogDebug($"Updating {objectKind} (FileReplacements not equal)"); + _logger.LogDebug("Updating {object}/{kind} (FileReplacements not equal)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Mods); } } @@ -105,7 +107,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable bool glamourerDataDifferent = !string.Equals(oldData.GlamourerData[objectKind], newData.GlamourerData[objectKind], StringComparison.Ordinal); if (forced || glamourerDataDifferent) { - _logger.LogDebug($"Updating {objectKind} (Diff glamourer data)"); + _logger.LogDebug("Updating {object}/{kind} (Diff glamourer data)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Mods); } } @@ -115,28 +117,31 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable bool manipDataDifferent = !string.Equals(oldData.ManipulationData, newData.ManipulationData, StringComparison.Ordinal); if (manipDataDifferent || forced) { - _logger.LogDebug($"Updating {objectKind} (Diff manip data)"); + _logger.LogDebug("Updating {object}/{kind} (Diff manip data)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Mods); continue; } bool heelsOffsetDifferent = oldData.HeelsOffset != newData.HeelsOffset; if (heelsOffsetDifferent || forced) - _logger.LogDebug($"Updating {objectKind} (Diff heels data)"); + { + _logger.LogDebug("Updating {object}/{kind} (Diff heels data)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Heels); continue; } bool customizeDataDifferent = !string.Equals(oldData.CustomizePlusData, newData.CustomizePlusData, StringComparison.Ordinal); if (customizeDataDifferent || forced) - _logger.LogDebug($"Updating {objectKind} (Diff customize data)"); + { + _logger.LogDebug("Updating {object}/{kind} (Diff customize data)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Customize); continue; } bool palettePlusDataDifferent = !string.Equals(oldData.PalettePlusData, newData.PalettePlusData, StringComparison.Ordinal); if (palettePlusDataDifferent || forced) - _logger.LogDebug($"Updating {objectKind} (Diff palette data)"); + { + _logger.LogDebug("Updating {object}/{kind} (Diff palette data)", this, objectKind); charaDataToUpdate[objectKind].Add(PlayerChanges.Palette); continue; } @@ -150,7 +155,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable } } - private enum PlayerChanges + public enum PlayerChanges { Heels = 1, Customize = 2, @@ -207,18 +212,18 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable return true; } - public override async void Dispose() + public override void Dispose() { if (string.IsNullOrEmpty(PlayerName)) return; // already disposed base.Dispose(); var name = PlayerName; PlayerName = null; - _logger.LogDebug("Disposing " + name + " (" + OnlineUser + ")"); + _logger.LogDebug("Disposing {name} ({user})", name, OnlineUser); try { Guid applicationId = Guid.NewGuid(); - _logger.LogTrace($"[{applicationId}] Restoring state for {name} ({OnlineUser})"); + _logger.LogTrace("[{applicationId}] Restoring state for {name} ({OnlineUser})", applicationId, name, OnlineUser); _currentOtherChara?.Dispose(); _ipcManager.PenumbraRemoveTemporaryCollection(_logger, applicationId, name); _downloadCancellationTokenSource?.Cancel(); @@ -228,19 +233,19 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable { foreach (var item in _cachedData.FileReplacements) { - await RevertCustomizationData(item.Key, name, applicationId).ConfigureAwait(false); + RevertCustomizationData(item.Key, name, applicationId).RunSynchronously(); } } _currentOtherChara = null; } catch (Exception ex) { - _logger.LogWarning(ex.Message + Environment.NewLine + ex.StackTrace); + _logger.LogWarning(ex, "Error on disposal of {name}", name); } finally { _cachedData = new(); - _logger.LogDebug("Disposing " + name + " complete"); + _logger.LogDebug("Disposing {name} complete", name); PlayerName = null; } } @@ -248,7 +253,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable public void Initialize(string name) { PlayerName = name; - _currentOtherChara = _gameObjectHandlerFactory.Create(ObjectKind.Player, () => _dalamudUtil.GetPlayerCharacterFromObjectTableByName(PlayerName)?.Address ?? IntPtr.Zero, false); + _currentOtherChara = _gameObjectHandlerFactory.Create(ObjectKind.Player, () => _dalamudUtil.GetPlayerCharacterFromObjectTableByName(PlayerName)?.Address ?? IntPtr.Zero, isWatched: false); _originalGlamourerData = _ipcManager.GlamourerGetCharacterCustomization(PlayerCharacter); _lastGlamourerData = _originalGlamourerData; @@ -262,7 +267,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable } }); - _logger.LogDebug("Initializing Player " + this); + _logger.LogDebug("Initializing Player {obj}", this); } public override string ToString() @@ -276,15 +281,14 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable _ipcManager.PenumbraSetTemporaryMods(_logger, applicationId, PlayerName!, moddedPaths, manipulationData); } private async Task ApplyCustomizationData(Guid applicationId, KeyValuePair> changes, API.Data.CharacterData charaData) - private async Task ApplyCustomizationData(ObjectKind objectKind) { if (PlayerCharacter == IntPtr.Zero) return; var handler = changes.Key switch { ObjectKind.Player => _currentOtherChara!, - ObjectKind.Companion => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetCompanion(PlayerCharacter), false), - ObjectKind.MinionOrMount => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetMinionOrMount(PlayerCharacter) ?? IntPtr.Zero, false), - ObjectKind.Pet => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetPet(PlayerCharacter), false), + ObjectKind.Companion => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetCompanion(PlayerCharacter), isWatched: false), + ObjectKind.MinionOrMount => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetMinionOrMount(PlayerCharacter), isWatched: false), + ObjectKind.Pet => _gameObjectHandlerFactory.Create(changes.Key, () => _dalamudUtil.GetPet(PlayerCharacter), isWatched: false), _ => throw new NotSupportedException("ObjectKind not supported: " + changes.Key) }; @@ -293,12 +297,11 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable applicationTokenSource.CancelAfter(TimeSpan.FromSeconds(30)); if (handler.Address == IntPtr.Zero) return; - _logger.LogDebug($"[{applicationId}] Applying Customization Data for {handler}"); + _logger.LogDebug("[{applicationId}] Applying Customization Data for {handler}", applicationId, handler); _dalamudUtil.WaitWhileCharacterIsDrawing(_logger, handler, applicationId, 30000); - () => minionOrMount.Value, false); foreach (var change in changes.Value) { - _logger.LogDebug($"[{applicationId}] Processing {change} for {handler}"); + _logger.LogDebug("[{applicationId}] Processing {change} for {handler}", applicationId, change, handler); switch (change) { case PlayerChanges.Palette: @@ -306,10 +309,10 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable break; case PlayerChanges.Customize: _ipcManager.CustomizePlusSetBodyScale(handler.Address, charaData.CustomizePlusData); - break; case PlayerChanges.Heels: _ipcManager.HeelsSetOffsetForPlayer(charaData.HeelsOffset, handler.Address); + break; case PlayerChanges.Mods: if (charaData.GlamourerData.TryGetValue(changes.Key, out var glamourerData)) { @@ -318,10 +321,10 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable else { await _ipcManager.PenumbraRedraw(_logger, handler, applicationId, applicationTokenSource.Token).ConfigureAwait(false); - } } break; } + break; } } @@ -329,7 +332,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable { if (!updatedData.Any()) { - _logger.LogDebug("Nothing to update for " + this); + _logger.LogDebug("Nothing to update for {obj}", this); } var updateModdedPaths = updatedData.Values.Any(v => v.Any(p => p == PlayerChanges.Mods)); @@ -352,8 +355,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable while ((toDownloadReplacements = TryCalculateModdedDictionary(charaData, out moddedPaths)).Count > 0 && attempts++ <= 10) { downloadId = _apiController.GetDownloadId(); - _logger.LogDebug("Downloading missing files for player " + PlayerName + ", kind: " + updatedData); - Logger.Debug("Downloading missing files for player " + PlayerName + ", kind: " + objectKind); + _logger.LogDebug("Downloading missing files for player {name}, {kind}", PlayerName, updatedData); if (toDownloadReplacements.Any()) { await _apiController.DownloadFiles(downloadId, toDownloadReplacements, downloadToken).ConfigureAwait(false); @@ -384,35 +386,38 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable } _applicationTask = Task.Run(async () => + { Guid applicationId = Guid.NewGuid(); - _logger.LogDebug($"[{applicationId}] Starting application task"); + _logger.LogDebug("[{applicationId}] Starting application task", applicationId); if (updateModdedPaths) - if (moddedPaths.Any()) { - ApplyBaseData(applicationId, moddedPaths, charaData.ManipulationData); - } + if (moddedPaths.Any()) + { + ApplyBaseData(applicationId, moddedPaths, charaData.ManipulationData); + } - foreach (var kind in updatedData) - await ApplyCustomizationData(applicationId, kind, charaData).ConfigureAwait(false); - await ApplyCustomizationData(kind).ConfigureAwait(false); + foreach (var kind in updatedData) + { + await ApplyCustomizationData(applicationId, kind, charaData).ConfigureAwait(false); + } } }); }, downloadToken).ContinueWith(task => - { - _downloadCancellationTokenSource = null; + { + _downloadCancellationTokenSource = null; - if (!task.IsCanceled) return; + if (!task.IsCanceled) return; - _logger.LogDebug("Application was cancelled"); - _apiController.CancelDownload(downloadId); - }); + _logger.LogDebug("Application was cancelled"); + _apiController.CancelDownload(downloadId); + }); } private Task? _applicationTask; - private CancellationTokenSource _redrawCts = new CancellationTokenSource(); + private CancellationTokenSource _redrawCts = new(); private void IpcManagerOnPenumbraRedrawEvent(PenumbraRedrawMessage msg) { @@ -425,13 +430,13 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable var token = _redrawCts.Token; Task.Run(async () => + { var applicationId = Guid.NewGuid(); _dalamudUtil.WaitWhileCharacterIsDrawing(_logger, _currentOtherChara!, applicationId, ct: token); _logger.LogDebug("Unauthorized character change detected"); await ApplyCustomizationData(applicationId, new(ObjectKind.Player, new HashSet(new[] { PlayerChanges.Palette, PlayerChanges.Customize, PlayerChanges.Heels, PlayerChanges.Mods })), _cachedData).ConfigureAwait(false); - await ApplyCustomizationData(ObjectKind.Player).ConfigureAwait(false); }, token); } @@ -442,27 +447,26 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable var cancelToken = new CancellationTokenSource(); cancelToken.CancelAfter(TimeSpan.FromSeconds(10)); - _logger.LogDebug($"[{applicationId}] Reverting all Customization for {OnlineUser.User.AliasOrUID}/{name} {objectKind}"); + _logger.LogDebug("[{applicationId}] Reverting all Customization for {alias}/{name} {objectKind}", applicationId, OnlineUser.User.AliasOrUID, name, objectKind); if (objectKind == ObjectKind.Player) { - _logger.LogDebug($"[{applicationId}] Restoring Customization for {OnlineUser.User.AliasOrUID}/{name}: {_originalGlamourerData}"); + _logger.LogDebug("[{applicationId}] Restoring Customization for {alias}/{name}: {data}", applicationId, OnlineUser.User.AliasOrUID, name, _originalGlamourerData); await _ipcManager.GlamourerApplyOnlyCustomization(_logger, _currentOtherChara!, _originalGlamourerData, applicationId, cancelToken.Token, fireAndForget: false).ConfigureAwait(false); - _logger.LogDebug($"[{applicationId}] Restoring Equipment for {OnlineUser.User.AliasOrUID}/{name}: {_lastGlamourerData}"); + _logger.LogDebug("[{applicationId}] Restoring Equipment for {alias}/{name}: {data}", applicationId, OnlineUser.User.AliasOrUID, name, _lastGlamourerData); await _ipcManager.GlamourerApplyOnlyEquipment(_logger, _currentOtherChara!, _lastGlamourerData, applicationId, cancelToken.Token, fireAndForget: true).ConfigureAwait(false); - _logger.LogDebug($"[{applicationId}] Restoring Heels for {OnlineUser.User.AliasOrUID}/{name}"); + _logger.LogDebug("[{applicationId}] Restoring Heels for {alias}/{name}", applicationId, OnlineUser.User.AliasOrUID, name); _ipcManager.HeelsRestoreOffsetForPlayer(PlayerCharacter); - _logger.LogDebug($"[{applicationId}] Restoring C+ for {OnlineUser.User.AliasOrUID}/{name}"); + _logger.LogDebug("[{applicationId}] Restoring C+ for {alias}/{name}", applicationId, OnlineUser.User.AliasOrUID, name); _ipcManager.CustomizePlusRevert(PlayerCharacter); _ipcManager.PalettePlusRemovePalette(PlayerCharacter); } else if (objectKind == ObjectKind.MinionOrMount) { var minionOrMount = _dalamudUtil.GetMinionOrMount(PlayerCharacter); - if (minionOrMount != null) + if (minionOrMount != IntPtr.Zero) { - using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.MinionOrMount, () => minionOrMount.Value, - false); + using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.MinionOrMount, () => minionOrMount, isWatched: false); await _ipcManager.PenumbraRedraw(_logger, tempHandler, applicationId, cancelToken.Token, fireAndForget: true).ConfigureAwait(false); } } @@ -471,8 +475,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable var pet = _dalamudUtil.GetPet(PlayerCharacter); if (pet != IntPtr.Zero) { - using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Pet, () => pet, - false); + using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Pet, () => pet, isWatched: false); await _ipcManager.PenumbraRedraw(_logger, tempHandler, applicationId, cancelToken.Token, fireAndForget: true).ConfigureAwait(false); } } @@ -481,8 +484,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable var companion = _dalamudUtil.GetCompanion(PlayerCharacter); if (companion != IntPtr.Zero) { - using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Pet, () => companion, - false); + using GameObjectHandler tempHandler = _gameObjectHandlerFactory.Create(ObjectKind.Pet, () => companion, isWatched: false); await _ipcManager.PenumbraRedraw(_logger, tempHandler, applicationId, cancelToken.Token, fireAndForget: true).ConfigureAwait(false); } } @@ -505,7 +507,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable } else { - _logger.LogTrace("Missing file: " + item.Hash); + _logger.LogTrace("Missing file: {hash}", item.Hash); missingFiles.Add(item); } } @@ -515,7 +517,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable { foreach (var gamePath in item.GamePaths) { - _logger.LogTrace("Adding file swap for " + gamePath + ":" + item.FileSwapPath); + _logger.LogTrace("Adding file swap for {path}: {fileSwap}", gamePath, item.FileSwapPath); moddedDictionary[gamePath] = item.FileSwapPath; } } @@ -524,7 +526,7 @@ public class CachedPlayer : MediatorSubscriberBase, IDisposable { PluginLog.Error(ex, "Something went wrong during calculation replacements"); } - _logger.LogDebug("ModdedPaths calculated, missing files: " + missingFiles.Count); + _logger.LogDebug("ModdedPaths calculated, missing files: {count}", missingFiles.Count); return missingFiles; } } \ No newline at end of file diff --git a/MareSynchronos/Managers/IpcManager.cs b/MareSynchronos/Managers/IpcManager.cs index ffeb6ef..7788d8f 100644 --- a/MareSynchronos/Managers/IpcManager.cs +++ b/MareSynchronos/Managers/IpcManager.cs @@ -66,7 +66,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable private readonly ConcurrentQueue _normalQueue = new(); private readonly ConcurrentQueue _gposeActionQueue = new(); - private ConcurrentDictionary _penumbraRedrawRequests = new(); + private readonly ConcurrentDictionary _penumbraRedrawRequests = new(); private CancellationTokenSource _disposalCts = new(); private bool _penumbraAvailable = false; @@ -163,7 +163,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable if (_gposeActionQueue.TryDequeue(out var action)) { if (action == null) return; - _logger.LogDebug("Execution action in gpose queue: " + action.Method); + _logger.LogDebug("Execution action in gpose queue: {method}", action.Method); action(); } } @@ -195,7 +195,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable if (ActionQueue.TryDequeue(out var action)) { if (action == null) return; - _logger.LogDebug("Execution action in queue: " + action.Method); + _logger.LogDebug("Execution action in queue: {method}", action.Method); action(); } } @@ -341,7 +341,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(character); if (gameObj != null) { - _logger.LogTrace("Applying Heels data to " + character.ToString("X")); + _logger.LogTrace("Applying Heels data to {chara}", character.ToString("X")); _heelsRegisterPlayer.InvokeAction(gameObj, offset); } }); @@ -355,7 +355,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(character); if (gameObj != null) { - _logger.LogTrace("Restoring Heels data to " + character.ToString("X")); + _logger.LogTrace("Restoring Heels data to {chara}", character.ToString("X")); _heelsUnregisterPlayer.InvokeAction(gameObj); } }); @@ -378,7 +378,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable if (gameObj is Character c) { string decodedScale = Encoding.UTF8.GetString(Convert.FromBase64String(scale)); - _logger.LogTrace("CustomizePlus applying for " + c.Address.ToString("X")); + _logger.LogTrace("CustomizePlus applying for {chara}", c.Address.ToString("X")); _customizePlusSetBodyScaleToCharacter!.InvokeAction(decodedScale, c); } }); @@ -392,13 +392,13 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(character); if (gameObj is Character c) { - _logger.LogTrace("CustomizePlus reverting for " + c.Address.ToString("X")); + _logger.LogTrace("CustomizePlus reverting for {chara}", c.Address.ToString("X")); _customizePlusRevert!.InvokeAction(c); } }); } - private async Task PenumbraRedrawAction(Microsoft.Extensions.Logging.ILogger logger, GameObjectHandler obj, Guid applicationId, Action action, CancellationToken token, bool fireAndForget) + private async Task PenumbraRedrawAction(ILogger logger, GameObjectHandler obj, Guid applicationId, Action action, bool fireAndForget, CancellationToken token) { Mediator.Publish(new PenumbraStartRedrawMessage(obj.Address)); @@ -428,7 +428,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(handler.Address); if (gameObj is Character c) { - await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyAll!.InvokeAction(customization, c), token, fireAndForget).ConfigureAwait(false); + await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyAll!.InvokeAction(customization, c), fireAndForget, token).ConfigureAwait(false); } } @@ -438,7 +438,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(handler.Address); if (gameObj is Character c) { - await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyOnlyEquipment!.InvokeAction(customization, c), token, fireAndForget).ConfigureAwait(false); + await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyOnlyEquipment!.InvokeAction(customization, c), fireAndForget, token).ConfigureAwait(false); } } @@ -448,7 +448,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(handler.Address); if (gameObj is Character c) { - await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyOnlyCustomization!.InvokeAction(customization, c), token, fireAndForget).ConfigureAwait(false); + await PenumbraRedrawAction(logger, handler, applicationId, () => _glamourerApplyOnlyCustomization!.InvokeAction(customization, c), fireAndForget, token).ConfigureAwait(false); } } @@ -501,7 +501,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(handler.Address); if (gameObj is Character c) { - await PenumbraRedrawAction(logger, handler, applicationId, () => _penumbraRedrawObject!.Invoke(c, RedrawType.Redraw), token, fireAndForget).ConfigureAwait(false); + await PenumbraRedrawAction(logger, handler, applicationId, () => _penumbraRedrawObject!.Invoke(c, RedrawType.Redraw), fireAndForget, token).ConfigureAwait(false); } } @@ -511,11 +511,11 @@ public class IpcManager : MediatorSubscriberBase, IDisposable ActionQueue.Enqueue(() => { var collName = "Mare_" + characterName; - logger.LogTrace($"[{applicationId}] Removing temp collection for {collName}"); + logger.LogTrace("[{applicationId}] Removing temp collection for {collName}", applicationId, collName); var ret = _penumbraRemoveTemporaryMod.Invoke("MareChara", collName, 0); - logger.LogTrace($"[{applicationId}] RemoveTemporaryMod: {ret}"); + logger.LogTrace("[{applicationId}] RemoveTemporaryMod: {ret}", applicationId, ret); var ret2 = _penumbraRemoveTemporaryCollection.Invoke(collName); - logger.LogTrace($"[{applicationId}] RemoveTemporaryCollection: {ret2}"); + logger.LogTrace("[{applicationId}] RemoveTemporaryCollection: {ret2}", applicationId, ret2); }); } @@ -550,16 +550,16 @@ public class IpcManager : MediatorSubscriberBase, IDisposable } var collName = "Mare_" + characterName; var ret = _penumbraCreateNamedTemporaryCollection.Invoke(collName); - logger.LogTrace($"[{applicationId}] Creating Temp Collection {collName}, Success: {ret}"); + logger.LogTrace("[{applicationId}] Creating Temp Collection {collName}, Success: {ret}", applicationId, collName, ret); var retAssign = _penumbraAssignTemporaryCollection.Invoke(collName, idx.Value, c: true); - logger.LogTrace($"[{applicationId}] Assigning Temp Collection {collName} to index {idx.Value}"); + logger.LogTrace("[{applicationId}] Assigning Temp Collection {collName} to index {idx}", applicationId, collName, idx.Value); foreach (var mod in modPaths) { - logger.LogTrace($"[{applicationId}] {mod.Key} => {mod.Value}"); + logger.LogTrace("[{applicationId}] Change: {from} => {to}", applicationId, mod.Key, mod.Value); } var ret2 = _penumbraAddTemporaryMod.Invoke("MareChara", collName, modPaths, manipulationData, 0); - logger.LogTrace($"[{applicationId}] Setting temp mods for {collName}, Success: {ret2}"); + logger.LogTrace("[{applicationId}] Setting temp mods for {collName}, Success: {ret2}", applicationId, collName, ret2); }); } @@ -617,12 +617,12 @@ public class IpcManager : MediatorSubscriberBase, IDisposable if (string.IsNullOrEmpty(decodedPalette)) { - _logger.LogTrace("PalettePlus removing for " + c.Address.ToString("X")); + _logger.LogTrace("PalettePlus removing for {addr}", c.Address.ToString("X")); _palettePlusRemoveCharaPalette!.InvokeAction(c); } else { - _logger.LogTrace("PalettePlus applying for " + c.Address.ToString("X")); + _logger.LogTrace("PalettePlus applying for {addr}", c.Address.ToString("X")); _palettePlusSetCharaPalette!.InvokeAction(c, decodedPalette); } } @@ -645,7 +645,7 @@ public class IpcManager : MediatorSubscriberBase, IDisposable var gameObj = _dalamudUtil.CreateGameObject(character); if (gameObj is Character c) { - _logger.LogTrace("PalettePlus removing for " + c.Address.ToString("X")); + _logger.LogTrace("PalettePlus removing for {addr}", c.Address.ToString("X")); _palettePlusRemoveCharaPalette!.InvokeAction(c); } }); diff --git a/MareSynchronos/Managers/ServerConfigurationManager.cs b/MareSynchronos/Managers/ServerConfigurationManager.cs index 5e5a5a3..807f9b8 100644 --- a/MareSynchronos/Managers/ServerConfigurationManager.cs +++ b/MareSynchronos/Managers/ServerConfigurationManager.cs @@ -228,7 +228,7 @@ public class ServerConfigurationManager CurrentServerTagStorage().ServerAvailablePairTags.Remove(tag); foreach (var uid in GetUidsForTag(tag)) { - RemoveTagForUid(uid, tag, false); + RemoveTagForUid(uid, tag, save: false); } _serverTagConfig.Save(); } diff --git a/MareSynchronos/Managers/TransientResourceManager.cs b/MareSynchronos/Managers/TransientResourceManager.cs index 1a91c73..b3a8c34 100644 --- a/MareSynchronos/Managers/TransientResourceManager.cs +++ b/MareSynchronos/Managers/TransientResourceManager.cs @@ -14,7 +14,7 @@ public class TransientResourceManager : MediatorSubscriberBase, IDisposable private readonly TransientConfigService _configurationService; private readonly DalamudUtil _dalamudUtil; - public IntPtr[] PlayerRelatedPointers = Array.Empty(); + public HashSet PlayerRelatedPointers = new(); private readonly string[] _fileTypesToHandle = new[] { "tmb", "pap", "avfx", "atex", "sklb", "eid", "phyb", "scd", "skp", "shpk" }; private string PlayerPersistentDataKey => _dalamudUtil.PlayerName + "_" + _dalamudUtil.WorldId; @@ -36,24 +36,33 @@ public class TransientResourceManager : MediatorSubscriberBase, IDisposable try { - _logger.LogDebug("Loaded persistent transient resource " + gamePath); + _logger.LogDebug("Loaded persistent transient resource {path}", gamePath); SemiTransientResources[ObjectKind.Player].Add(gamePath); restored++; } catch (Exception ex) { - _logger.LogWarning("Error during loading persistent transient resource " + gamePath, ex); + _logger.LogWarning(ex, "Error during loading persistent transient resource {path}", gamePath); } } - _logger.LogDebug($"Restored {restored}/{gamePaths.Count()} semi persistent resources"); + _logger.LogDebug("Restored {restored}/{total} semi persistent resources", restored, gamePaths.Count()); } Mediator.Subscribe(this, (msg) => Manager_PenumbraResourceLoadEvent((PenumbraResourceLoadMessage)msg)); Mediator.Subscribe(this, (_) => Manager_PenumbraModSettingChanged()); Mediator.Subscribe(this, (_) => DalamudUtil_FrameworkUpdate()); Mediator.Subscribe(this, (_) => DalamudUtil_ClassJobChanged()); - Mediator.Subscribe(this, (msg) => PlayerRelatedPointers = ((PlayerRelatedObjectPointerUpdateMessage)msg).RelatedObjects); + Mediator.Subscribe(this, (msg) => + { + var actualMsg = ((AddWatchedGameObjectHandler)msg); + PlayerRelatedPointers.Add(actualMsg.Handler); + }); + Mediator.Subscribe(this, (msg) => + { + var actualMsg = ((RemoveWatchedGameObjectHandler)msg); + PlayerRelatedPointers.Remove(actualMsg.Handler); + }); } private void Manager_PenumbraModSettingChanged() @@ -134,7 +143,7 @@ public class TransientResourceManager : MediatorSubscriberBase, IDisposable { return; } - if (!PlayerRelatedPointers.Contains(gameObject)) + if (!PlayerRelatedPointers.Select(p => p.Address).Contains(gameObject)) { //_logger.LogDebug("Got resource " + gamePath + " for ptr " + gameObject.ToString("X")); return; @@ -158,12 +167,12 @@ public class TransientResourceManager : MediatorSubscriberBase, IDisposable if (TransientResources[gameObject].Contains(replacedGamePath) || SemiTransientResources.Any(r => r.Value.Any(f => string.Equals(f, gamePath, StringComparison.OrdinalIgnoreCase)))) { - _logger.LogTrace("Not adding " + replacedGamePath + ":" + filePath); + _logger.LogTrace("Not adding {replacedPath} : {filePath}", replacedGamePath, filePath); } else { TransientResources[gameObject].Add(replacedGamePath); - _logger.LogDebug($"Adding {replacedGamePath} for {gameObject} ({filePath})"); + _logger.LogDebug("Adding {replacedGamePath} for {gameObject} ({filePath})", replacedGamePath, gameObject, filePath); Mediator.Publish(new TransientResourceChangedMessage(gameObject)); } } diff --git a/MareSynchronos/MareConfiguration/ConfigurationMigrator.cs b/MareSynchronos/MareConfiguration/ConfigurationMigrator.cs index 35d5630..1d0edc2 100644 --- a/MareSynchronos/MareConfiguration/ConfigurationMigrator.cs +++ b/MareSynchronos/MareConfiguration/ConfigurationMigrator.cs @@ -45,7 +45,7 @@ public class ConfigurationMigrator { _logger.LogInformation("Migrating Configuration from version 0 to 1"); if (File.Exists(ConfigurationPath(MareConfigService.ConfigName))) - File.Copy(ConfigurationPath(MareConfigService.ConfigName), ConfigurationPath(MareConfigService.ConfigName) + ".migrated." + mareConfigV0.Version + ".bak", true); + File.Copy(ConfigurationPath(MareConfigService.ConfigName), ConfigurationPath(MareConfigService.ConfigName) + ".migrated." + mareConfigV0.Version + ".bak", overwrite: true); MareConfig mareConfigV1 = mareConfigV0.ToV1(); diff --git a/MareSynchronos/MareConfiguration/ConfigurationServiceBase.cs b/MareSynchronos/MareConfiguration/ConfigurationServiceBase.cs index 42e44b1..63d32e5 100644 --- a/MareSynchronos/MareConfiguration/ConfigurationServiceBase.cs +++ b/MareSynchronos/MareConfiguration/ConfigurationServiceBase.cs @@ -102,7 +102,7 @@ public abstract class ConfigurationServiceBase : IDisposable where T : IMareC try { - File.Copy(ConfigurationPath, ConfigurationPath + ".bak." + DateTime.Now.ToString("yyyyMMddHHmmss"), true); + File.Copy(ConfigurationPath, ConfigurationPath + ".bak." + DateTime.Now.ToString("yyyyMMddHHmmss"), overwrite: true); } catch { } diff --git a/MareSynchronos/MareConfiguration/Configurations/MareConfig.cs b/MareSynchronos/MareConfiguration/Configurations/MareConfig.cs index 7e6d76a..59396e4 100644 --- a/MareSynchronos/MareConfiguration/Configurations/MareConfig.cs +++ b/MareSynchronos/MareConfiguration/Configurations/MareConfig.cs @@ -26,4 +26,5 @@ public class MareConfig : IMareConfiguration public NotificationLocation WarningNotification { get; set; } = NotificationLocation.Both; public NotificationLocation ErrorNotification { get; set; } = NotificationLocation.Both; public LogLevel LogLevel { get; set; } = LogLevel.Information; + public bool LogPerformance { get; set; } = false; } diff --git a/MareSynchronos/MareConfiguration/Configurations/Obsolete/Configuration.cs b/MareSynchronos/MareConfiguration/Configurations/Obsolete/Configuration.cs index d1b5a49..79b6ad0 100644 --- a/MareSynchronos/MareConfiguration/Configurations/Obsolete/Configuration.cs +++ b/MareSynchronos/MareConfiguration/Configurations/Obsolete/Configuration.cs @@ -11,8 +11,6 @@ namespace MareSynchronos.MareConfiguration.Configurations.Obsolete; public class Configuration : IPluginConfiguration { public int Version { get; set; } = 6; - [NonSerialized] - private DalamudPluginInterface? _pluginInterface; public Dictionary ServerStorage { get; set; } = new(StringComparer.OrdinalIgnoreCase) { { ApiController.MainServiceUri, new ServerStorageV0() { ServerName = ApiController.MainServer, ServerUri = ApiController.MainServiceUri } }, @@ -55,12 +53,6 @@ public class Configuration : IPluginConfiguration public Dictionary> ServerAvailablePairTags = new(StringComparer.Ordinal); public HashSet OpenPairTags = new(StringComparer.Ordinal); - - public void Save() - { - _pluginInterface!.SavePluginConfig(this); - } - public MareConfigV0 ToMareConfig(ILogger logger) { diff --git a/MareSynchronos/MarePlugin.cs b/MareSynchronos/MarePlugin.cs index 805553f..a506790 100644 --- a/MareSynchronos/MarePlugin.cs +++ b/MareSynchronos/MarePlugin.cs @@ -156,7 +156,7 @@ public class MarePlugin : MediatorSubscriberBase, IDisposable } catch (Exception ex) { - _logger?.LogWarning(ex.Message); + _logger?.LogCritical(ex, "Error during launch of managers"); } } @@ -203,6 +203,17 @@ public class MarePlugin : MediatorSubscriberBase, IDisposable { _serviceProvider.GetRequiredService().InvokeScan(forced: true); } + else if (string.Equals(splitArgs[0], "perf", StringComparison.OrdinalIgnoreCase)) + { + if (splitArgs.Length > 1 && int.TryParse(splitArgs[1], out var limitBySeconds)) + { + _serviceProvider.GetRequiredService().PrintPerformanceStats(limitBySeconds); + } + else + { + _serviceProvider.GetRequiredService().PrintPerformanceStats(); + } + } } private void OpenUi() diff --git a/MareSynchronos/Mediator/MareMediator.cs b/MareSynchronos/Mediator/MareMediator.cs index eece0bc..c6e2de6 100644 --- a/MareSynchronos/Mediator/MareMediator.cs +++ b/MareSynchronos/Mediator/MareMediator.cs @@ -1,4 +1,6 @@ -using Microsoft.Extensions.Logging; +using MareSynchronos.Utils; +using Microsoft.Extensions.Logging; +using System.Diagnostics; namespace MareSynchronos.Mediator; @@ -8,10 +10,12 @@ public class MareMediator : IDisposable private readonly Dictionary> _subscriberDict = new(); private readonly ILogger _logger; + private readonly PerformanceCollector _performanceCollector; - public MareMediator(ILogger logger) + public MareMediator(ILogger logger, PerformanceCollector performanceCollector) { _logger = logger; + _performanceCollector = performanceCollector; } public void Subscribe(IMediatorSubscriber subscriber, Action action) where T : IMessage @@ -36,18 +40,22 @@ public class MareMediator : IDisposable { if (_subscriberDict.TryGetValue(message.GetType(), out var subscribers)) { - foreach (var subscriber in subscribers.ToList()) + Stopwatch globalStopwatch = Stopwatch.StartNew(); + _performanceCollector.LogPerformance(this, $"Publish>{message.GetType().Name}", () => { - try + foreach (var subscriber in subscribers.ToList()) { - subscriber.Action.Invoke(message); + try + { + _performanceCollector.LogPerformance(this, $"Publish>{message.GetType().Name}+{subscriber.Subscriber.GetType().Name}", () => subscriber.Action.Invoke(message)); + } + catch (Exception ex) + { + _logger.LogCritical(ex, "Error executing {type} for subscriber {subscriber}, removing from Mediator", message.GetType(), subscriber); + subscribers.RemoveWhere(s => s == subscriber); + } } - catch (Exception ex) - { - _logger.LogCritical("Error executing " + message.GetType() + " for subscriber " + subscriber + ", removing from Mediator", ex); - subscribers.RemoveWhere(s => s == subscriber); - } - } + }); } } @@ -57,13 +65,13 @@ public class MareMediator : IDisposable { var unSubbed = kvp.Value.RemoveWhere(p => p.Subscriber == subscriber); if (unSubbed > 0) - _logger.LogTrace(subscriber + " unsubscribed from " + kvp.Key.Name); + _logger.LogDebug("{sub} unsubscribed from {msg}", subscriber, kvp.Key.Name); } } public void Dispose() { - _logger.LogTrace($"Disposing {GetType()}"); + _logger.LogTrace("Disposing {type}", GetType()); _subscriberDict.Clear(); } } \ No newline at end of file diff --git a/MareSynchronos/Mediator/Messages.cs b/MareSynchronos/Mediator/Messages.cs index c2de0be..950f1a8 100644 --- a/MareSynchronos/Mediator/Messages.cs +++ b/MareSynchronos/Mediator/Messages.cs @@ -32,8 +32,8 @@ public record PalettePlusMessage(string? Data) : IMessage; public record PlayerChangedMessage(API.Data.CharacterData Data) : IMessage; public record CharacterChangedMessage(GameObjectHandler GameObjectHandler) : IMessage; public record TransientResourceChangedMessage(IntPtr Address) : IMessage; -public record PlayerRelatedObjectPointerUpdateMessage(IntPtr[] RelatedObjects) : IMessage; - +public record AddWatchedGameObjectHandler(GameObjectHandler Handler) : IMessage; +public record RemoveWatchedGameObjectHandler(GameObjectHandler Handler) : IMessage; public record HaltScanMessage(string Source) : IMessage; public record ResumeScanMessage(string Source) : IMessage; diff --git a/MareSynchronos/Models/GameObjectHandler.cs b/MareSynchronos/Models/GameObjectHandler.cs index 2004499..f5dc1e6 100644 --- a/MareSynchronos/Models/GameObjectHandler.cs +++ b/MareSynchronos/Models/GameObjectHandler.cs @@ -6,15 +6,16 @@ using Penumbra.String; using MareSynchronos.Mediator; using ObjectKind = MareSynchronos.API.Data.Enum.ObjectKind; using Microsoft.Extensions.Logging; +using MareSynchronos.Utils; namespace MareSynchronos.Models; public class GameObjectHandler : MediatorSubscriberBase { + private readonly PerformanceCollector _performanceCollector; private readonly MareMediator _mediator; private readonly Func _getAddress; - private readonly bool _sendUpdates; - + private readonly bool _isOwnedObject; public unsafe Character* Character => (Character*)Address; public string Name { get; private set; } @@ -27,15 +28,16 @@ public class GameObjectHandler : MediatorSubscriberBase public override string ToString() { - return $"{Name} ({Address.ToString("X")},{DrawObjectAddress.ToString("X")})"; + return $"{ObjectKind}:{Name} ({Address:X},{DrawObjectAddress:X})"; } - public GameObjectHandler(ILogger logger, MareMediator mediator, ObjectKind objectKind, Func getAddress, bool watchedObject = true) : base(logger, mediator) + public GameObjectHandler(ILogger logger, PerformanceCollector performanceCollector, MareMediator mediator, ObjectKind objectKind, Func getAddress, bool watchedObject = true) : base(logger, mediator) { + _performanceCollector = performanceCollector; _mediator = mediator; ObjectKind = objectKind; _getAddress = getAddress; - _sendUpdates = watchedObject; + _isOwnedObject = watchedObject; Name = string.Empty; if (watchedObject) @@ -49,6 +51,7 @@ public class GameObjectHandler : MediatorSubscriberBase Mediator.Publish(new CreateCacheForObjectMessage(this)); } }); + Mediator.Publish(new AddWatchedGameObjectHandler(this)); } Mediator.Subscribe(this, (_) => FrameworkUpdate()); @@ -82,16 +85,23 @@ public class GameObjectHandler : MediatorSubscriberBase CheckAndUpdateObject(); } + public override void Dispose() + { + base.Dispose(); + Mediator.Publish(new RemoveWatchedGameObjectHandler(this)); + } + private void FrameworkUpdate() { if (!_delayedZoningTask?.IsCompleted ?? false) return; - CheckAndUpdateObject(); + _performanceCollector.LogPerformance(this, "CheckAndUpdateObject>" + (_isOwnedObject ? "Self+" : "Other+") + ObjectKind + "/" + + (string.IsNullOrEmpty(Name) ? "Unk" : Name) + "+" + Address.ToString("X"), CheckAndUpdateObject); } private void ZoneSwitchEnd() { - if (!_sendUpdates || _haltProcessing) return; + if (!_isOwnedObject || _haltProcessing) return; _clearCts?.Cancel(); _clearCts?.Dispose(); @@ -101,10 +111,10 @@ public class GameObjectHandler : MediatorSubscriberBase private void ZoneSwitchStart() { - if (!_sendUpdates || _haltProcessing) return; + if (!_isOwnedObject || _haltProcessing) return; _zoningCts = new(); - _logger.LogDebug($"[{this}] Starting Delay After Zoning"); + _logger.LogDebug("[{obj}] Starting Delay After Zoning", this); _delayedZoningTask = Task.Run(async () => { try @@ -114,7 +124,7 @@ public class GameObjectHandler : MediatorSubscriberBase catch { } finally { - _logger.LogDebug($"[{this}] Delay after zoning complete"); + _logger.LogDebug("[{this}] Delay after zoning complete", this); _zoningCts.Dispose(); } }); @@ -127,7 +137,6 @@ public class GameObjectHandler : MediatorSubscriberBase private CancellationTokenSource? _clearCts = new(); private byte? HatState { get; set; } private byte? VisorWeaponState { get; set; } - private bool _doNotSendUpdate; private unsafe void CheckAndUpdateObject() { @@ -135,16 +144,22 @@ public class GameObjectHandler : MediatorSubscriberBase bool drawObjDiff = false; try { - var drawObjAddr = (IntPtr)((GameObject*)curPtr)->GetDrawObject(); - drawObjDiff = drawObjAddr != DrawObjectAddress; - DrawObjectAddress = drawObjAddr; + if (curPtr != IntPtr.Zero) + { + var drawObjAddr = (IntPtr)((GameObject*)curPtr)->GetDrawObject(); + drawObjDiff = drawObjAddr != DrawObjectAddress; + DrawObjectAddress = drawObjAddr; - IsBeingDrawn = (((CharacterBase*)drawObjAddr)->HasModelInSlotLoaded != 0) - || (((CharacterBase*)drawObjAddr)->HasModelFilesInSlotLoaded != 0) - || (((GameObject*)curPtr)->RenderFlags & 0b100000000000) == 0b100000000000; + IsBeingDrawn = DrawObjectAddress == IntPtr.Zero || (((CharacterBase*)DrawObjectAddress)->HasModelInSlotLoaded != 0) + || (((CharacterBase*)DrawObjectAddress)->HasModelFilesInSlotLoaded != 0) + || (((GameObject*)curPtr)->RenderFlags & 0b100000000000) == 0b100000000000; + } } - catch + catch (Exception ex) { + var name = new ByteString(((Character*)curPtr)->GameObject.Name).ToString(); + + _logger.LogError(ex, "Error during checking for draw object for {name}", this); if (curPtr != IntPtr.Zero) { IsBeingDrawn = true; @@ -157,40 +172,43 @@ public class GameObjectHandler : MediatorSubscriberBase { if (_clearCts != null) { - _logger.LogDebug($"[{this}] Cancelling Clear Task"); + _logger.LogDebug("[{this}] Cancelling Clear Task", this); _clearCts?.Cancel(); _clearCts = null; } bool addrDiff = Address != curPtr; Address = curPtr; var chara = (Character*)curPtr; - bool equipDiff = CompareAndUpdateEquipByteData(chara->EquipSlotData); - var customizeDiff = _sendUpdates ? CompareAndUpdateCustomizeData(chara->CustomizeData) : false; var name = new ByteString(chara->GameObject.Name).ToString(); bool nameChange = (!string.Equals(name, Name, StringComparison.Ordinal)); + Name = name; + bool equipDiff = CompareAndUpdateEquipByteData(chara->EquipSlotData); + if (equipDiff && !_isOwnedObject) // send the message out immediately and cancel out, no reason to continue if not self + { + _logger.LogTrace("[{this}] Changed", this); + Mediator.Publish(new CharacterChangedMessage(this)); + return; + } + + var customizeDiff = CompareAndUpdateCustomizeData(chara->CustomizeData, out bool doNotSendUpdate); + if (addrDiff || equipDiff || customizeDiff || drawObjDiff || nameChange) { - Name = name; - _logger.LogTrace($"[{this}] Changed"); + _logger.LogTrace("[{this}] Changed", this); - if (_sendUpdates && !_doNotSendUpdate) + if (_isOwnedObject && !doNotSendUpdate) { - _logger.LogDebug($"[{this}] Sending CreateCacheObjectMessage"); + _logger.LogDebug("[{this}] Sending CreateCacheObjectMessage", this); Mediator.Publish(new CreateCacheForObjectMessage(this)); } - - if (equipDiff && !_sendUpdates) - { - Mediator.Publish(new CharacterChangedMessage(this)); - } } } else if (Address != IntPtr.Zero || DrawObjectAddress != IntPtr.Zero) { Address = IntPtr.Zero; DrawObjectAddress = IntPtr.Zero; - _logger.LogTrace($"[{this}] Changed -> Null"); - if (_sendUpdates && ObjectKind != ObjectKind.Player) + _logger.LogTrace("[{this}] Changed -> Null", this); + if (_isOwnedObject && ObjectKind != ObjectKind.Player) { _clearCts?.Cancel(); _clearCts?.Dispose(); @@ -203,9 +221,9 @@ public class GameObjectHandler : MediatorSubscriberBase private async Task ClearTask(CancellationToken token) { - _logger.LogDebug($"[{this}] Running Clear Task"); + _logger.LogDebug("[{this}] Running Clear Task", this); await Task.Delay(TimeSpan.FromSeconds(1), token).ConfigureAwait(false); - _logger.LogDebug($"[{this}] Sending ClearCachedForObjectMessage"); + _logger.LogDebug("[{this}] Sending ClearCachedForObjectMessage", this); Mediator.Publish(new ClearCacheForObjectMessage(this)); _clearCts = null; } @@ -226,10 +244,10 @@ public class GameObjectHandler : MediatorSubscriberBase return hasChanges; } - private unsafe bool CompareAndUpdateCustomizeData(byte* customizeData) + private unsafe bool CompareAndUpdateCustomizeData(byte* customizeData, out bool doNotSendUpdate) { bool hasChanges = false; - _doNotSendUpdate = false; + doNotSendUpdate = false; for (int i = 0; i < CustomizeData.Length; i++) { @@ -247,8 +265,8 @@ public class GameObjectHandler : MediatorSubscriberBase { if (HatState != null && !hasChanges) { - _logger.LogDebug($"[{this}] Not Sending Update, only Hat changed"); - _doNotSendUpdate = true; + _logger.LogDebug("[{this}] Not Sending Update, only Hat changed", this); + doNotSendUpdate = true; } HatState = newHatState; } @@ -259,8 +277,8 @@ public class GameObjectHandler : MediatorSubscriberBase { if (VisorWeaponState != null && !hasChanges) { - _logger.LogDebug($"[{this}] Not Sending Update, only Visor/Weapon changed"); - _doNotSendUpdate = true; + _logger.LogDebug("[{this}] Not Sending Update, only Visor/Weapon changed", this); + doNotSendUpdate = true; } VisorWeaponState = newWeaponOrVisorState; } diff --git a/MareSynchronos/Plugin.cs b/MareSynchronos/Plugin.cs index 0327f32..42e008c 100644 --- a/MareSynchronos/Plugin.cs +++ b/MareSynchronos/Plugin.cs @@ -24,7 +24,7 @@ namespace MareSynchronos; public sealed class Plugin : IDalamudPlugin { - private readonly MarePlugin plugin; + private readonly MarePlugin _plugin; public string Name => "Mare Synchronos"; private readonly ILogger _pluginLogger; @@ -73,6 +73,7 @@ public sealed class Plugin : IDalamudPlugin collection.AddSingleton(); collection.AddSingleton(); collection.AddSingleton(); + collection.AddSingleton(); collection.AddSingleton(); collection.AddSingleton(); @@ -96,12 +97,12 @@ public sealed class Plugin : IDalamudPlugin var mediator = serviceProvider.GetRequiredService(); var logger = serviceProvider.GetRequiredService>(); - plugin = new MarePlugin(logger, serviceProvider, mediator); + _plugin = new MarePlugin(logger, serviceProvider, mediator); } public void Dispose() { _pluginLogger.LogTrace($"Disposing {GetType()}"); - plugin.Dispose(); + _plugin.Dispose(); } } diff --git a/MareSynchronos/UI/CompactUI.cs b/MareSynchronos/UI/CompactUI.cs index 52cd56d..73fb02c 100644 --- a/MareSynchronos/UI/CompactUI.cs +++ b/MareSynchronos/UI/CompactUI.cs @@ -748,7 +748,7 @@ public class CompactUi : WindowMediatorSubscriberBase, IDisposable _serverManager.Save(); - _ = _apiController.CreateConnections(true); + _ = _apiController.CreateConnections(forceGetToken: true); } _uiShared.DrawCombo("Secret Key##addCharacterSecretKey", keys, (f) => f.Value.FriendlyName, (f) => secretKeyIdx = f.Key); diff --git a/MareSynchronos/UI/SettingsUi.cs b/MareSynchronos/UI/SettingsUi.cs index 811ed26..8a661d5 100644 --- a/MareSynchronos/UI/SettingsUi.cs +++ b/MareSynchronos/UI/SettingsUi.cs @@ -15,6 +15,7 @@ using MareSynchronos.MareConfiguration; using MareSynchronos.Mediator; using MareSynchronos.MareConfiguration.Models; using Microsoft.Extensions.Logging; +using MareSynchronos.Utils; namespace MareSynchronos.UI; @@ -26,6 +27,7 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable private readonly MareCharaFileManager _mareCharaFileManager; private readonly PairManager _pairManager; private readonly ServerConfigurationManager _serverConfigurationManager; + private readonly PerformanceCollector _performanceCollector; private readonly UiShared _uiShared; public CharacterData? LastCreatedCharacterData { private get; set; } @@ -37,7 +39,8 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable public SettingsUi(ILogger logger, WindowSystem windowSystem, UiShared uiShared, MareConfigService configService, MareCharaFileManager mareCharaFileManager, PairManager pairManager, - ServerConfigurationManager serverConfigurationManager, MareMediator mediator) : base(logger, mediator, "Mare Synchronos Settings") + ServerConfigurationManager serverConfigurationManager, + MareMediator mediator, PerformanceCollector performanceCollector) : base(logger, mediator, "Mare Synchronos Settings") { _logger.LogTrace("Creating " + nameof(SettingsUi)); @@ -52,6 +55,7 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable _mareCharaFileManager = mareCharaFileManager; _pairManager = pairManager; _serverConfigurationManager = serverConfigurationManager; + _performanceCollector = performanceCollector; _uiShared = uiShared; Mediator.Subscribe(this, (_) => Toggle()); @@ -545,7 +549,6 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable private bool _deleteFilesPopupModalShown = false; private bool _deleteAccountPopupModalShown = false; - private void DrawDebug() { _lastTab = "Debug"; @@ -565,11 +568,31 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable } UiShared.AttachToolTip("Use this when reporting mods being rejected from the server."); - _uiShared.DrawCombo("Log Level", Enum.GetValues(), (l) => l.ToString(), (l) => + _uiShared.DrawCombo("Log Level", Enum.GetValues(), (l) => l.ToString(), (l) => { _configService.Current.LogLevel = l; _configService.Save(); }, _configService.Current.LogLevel); + + bool logPerformance = _configService.Current.LogPerformance; + if (ImGui.Checkbox("Log Performance Counters", ref logPerformance)) + { + _configService.Current.LogPerformance = logPerformance; + _configService.Save(); + } + UiShared.DrawHelpText("Enabling this can incur a (slight) performance impact. Enabling this for extended periods of time is not recommended."); + + if (!logPerformance) ImGui.BeginDisabled(); + if (UiShared.IconTextButton(FontAwesomeIcon.StickyNote, "Print Performance Stats to /xllog")) + { + _performanceCollector.PrintPerformanceStats(); + } + ImGui.SameLine(); + if (UiShared.IconTextButton(FontAwesomeIcon.StickyNote, "Print Performance Stats (last 60s) to /xllog")) + { + _performanceCollector.PrintPerformanceStats(60); + } + if (!logPerformance) ImGui.EndDisabled(); } private void DrawBlockedTransfers() @@ -725,7 +748,7 @@ public class SettingsUi : WindowMediatorSubscriberBase, IDisposable } catch (Exception ex) { - _logger.LogCritical("Error saving data", ex); + _logger.LogCritical(ex, "Error saving data"); } }); }); diff --git a/MareSynchronos/UI/UIShared.cs b/MareSynchronos/UI/UIShared.cs index 2650f28..6ea3def 100644 --- a/MareSynchronos/UI/UIShared.cs +++ b/MareSynchronos/UI/UIShared.cs @@ -41,7 +41,7 @@ public partial class UiShared : MediatorSubscriberBase public string PlayerName => _dalamudUtil.PlayerName; public uint WorldId => _dalamudUtil.WorldId; public Dictionary WorldData => _dalamudUtil.WorldData.Value; - private Dictionary _selectedComboItems = new(StringComparer.Ordinal); + private readonly Dictionary _selectedComboItems = new(StringComparer.Ordinal); public bool HasValidPenumbraModPath => !(_ipcManager.PenumbraModDirectory ?? string.Empty).IsNullOrEmpty() && Directory.Exists(_ipcManager.PenumbraModDirectory); public bool EditTrackerPosition { get; set; } public ImFontPtr UidFont { get; private set; } @@ -114,7 +114,8 @@ public partial class UiShared : MediatorSubscriberBase { selectedItem = initialSelectedItem; _selectedComboItems[comboName] = selectedItem!; - onSelected?.Invoke(initialSelectedItem); + if (!EqualityComparer.Default.Equals(initialSelectedItem, default)) + onSelected?.Invoke(initialSelectedItem); } else { @@ -155,13 +156,12 @@ public partial class UiShared : MediatorSubscriberBase } catch (Exception ex) { - _logger.LogWarning($"Font failed to load. {fontFile}"); - _logger.LogWarning(ex.ToString()); + _logger.LogWarning(ex, "Font failed to load. {fontFile}", fontFile); } } else { - _logger.LogDebug($"Font doesn't exist. {fontFile}"); + _logger.LogDebug("Font doesn't exist. {fontFile}", fontFile); } } @@ -522,7 +522,7 @@ public partial class UiShared : MediatorSubscriberBase _isPenumbraDirectory = string.Equals(path.ToLowerInvariant(), _ipcManager.PenumbraModDirectory?.ToLowerInvariant(), StringComparison.Ordinal); _isDirectoryWritable = IsDirectoryWritable(path); _cacheDirectoryHasOtherFilesThanCache = Directory.GetFiles(path, "*", SearchOption.AllDirectories).Any(f => new FileInfo(f).Name.Length != 40); - _cacheDirectoryIsValidPath = Regex.IsMatch(path, @"^(?:[a-zA-Z]:\\[\w\s\-\\]+?|\/(?:[\w\s\-\/])+?)$", RegexOptions.ECMAScript); + _cacheDirectoryIsValidPath = PathRegex().IsMatch(path); if (!string.IsNullOrEmpty(path) && Directory.Exists(path) @@ -586,8 +586,8 @@ public partial class UiShared : MediatorSubscriberBase { if (throwIfFails) throw; - else - return false; + + return false; } } @@ -663,7 +663,7 @@ public partial class UiShared : MediatorSubscriberBase var note = entry.GetNote(); if (note.IsNullOrEmpty()) continue; - sb.AppendLine(entry.UserData.UID + ":\"" + entry.GetNote() + "\""); + sb.Append(entry.UserData.UID).Append(":\"").Append(entry.GetNote()).AppendLine("\""); } sb.AppendLine(_notesEnd); @@ -675,12 +675,12 @@ public partial class UiShared : MediatorSubscriberBase var splitNotes = notes.Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries).ToList(); var splitNotesStart = splitNotes.FirstOrDefault(); var splitNotesEnd = splitNotes.LastOrDefault(); - if (!string.Equals(splitNotesStart, _notesStart) || !string.Equals(splitNotesEnd, _notesEnd)) + if (!string.Equals(splitNotesStart, _notesStart, StringComparison.Ordinal) || !string.Equals(splitNotesEnd, _notesEnd, StringComparison.Ordinal)) { return false; } - splitNotes.RemoveAll(n => string.Equals(n, _notesStart) || string.Equals(n, _notesEnd)); + splitNotes.RemoveAll(n => string.Equals(n, _notesStart, StringComparison.Ordinal) || string.Equals(n, _notesEnd, StringComparison.Ordinal)); foreach (var note in splitNotes) { @@ -694,7 +694,7 @@ public partial class UiShared : MediatorSubscriberBase } catch { - _logger.LogWarning("Could not parse " + note); + _logger.LogWarning("Could not parse {note}", note); } } @@ -708,4 +708,7 @@ public partial class UiShared : MediatorSubscriberBase base.Dispose(); _pluginInterface.UiBuilder.BuildFonts -= BuildFont; } + + [GeneratedRegex(@"^(?:[a-zA-Z]:\\[\w\s\-\\]+?|\/(?:[\w\s\-\/])+?)$", RegexOptions.ECMAScript)] + private static partial Regex PathRegex(); } diff --git a/MareSynchronos/Utils/DalamudLogger.cs b/MareSynchronos/Utils/DalamudLogger.cs index f7093e0..8fa1ef4 100644 --- a/MareSynchronos/Utils/DalamudLogger.cs +++ b/MareSynchronos/Utils/DalamudLogger.cs @@ -1,6 +1,7 @@ using Dalamud.Logging; using MareSynchronos.MareConfiguration; using Microsoft.Extensions.Logging; +using System.Text; namespace MareSynchronos.Utils; @@ -20,13 +21,19 @@ internal class DalamudLogger : ILogger if (!IsEnabled(logLevel)) return; if (exception == null) - PluginLog.Information($"[{_name}]{{{(int)logLevel}}} {formatter(state, exception)}"); - else if (logLevel == LogLevel.Warning) - PluginLog.Warning($"[{_name}]{{{(int)logLevel}}} {formatter(state, exception)}"); - else if (logLevel == LogLevel.Error) - PluginLog.Error($"[{_name}]{{{(int)logLevel}}} {formatter(state, exception)}"); + PluginLog.Information($"[{_name}]{{{(int)logLevel}}} {state}"); else - PluginLog.Fatal($"[{_name}]{{{(int)logLevel}}} {formatter(state, exception)}"); + { + StringBuilder sb = new(); + sb.AppendLine($"[{_name}]{{{(int)logLevel}}} {state}: {exception.Message}"); + sb.AppendLine(exception.StackTrace); + if (logLevel == LogLevel.Warning) + PluginLog.Warning(sb.ToString()); + else if (logLevel == LogLevel.Error) + PluginLog.Error(sb.ToString()); + else + PluginLog.Fatal(sb.ToString()); + } } public bool IsEnabled(LogLevel logLevel) diff --git a/MareSynchronos/Utils/DalamudUtil.cs b/MareSynchronos/Utils/DalamudUtil.cs index ddba7f8..1f9a375 100644 --- a/MareSynchronos/Utils/DalamudUtil.cs +++ b/MareSynchronos/Utils/DalamudUtil.cs @@ -8,6 +8,7 @@ using FFXIVClientStructs.FFXIV.Client.Game.Control; using MareSynchronos.Mediator; using MareSynchronos.Models; using Microsoft.Extensions.Logging; +using System.Diagnostics; using GameObject = FFXIVClientStructs.FFXIV.Client.Game.Object.GameObject; namespace MareSynchronos.Utils; @@ -20,7 +21,7 @@ public class DalamudUtil : IDisposable private readonly Framework _framework; private readonly Condition _condition; private readonly MareMediator _mediator; - + private readonly PerformanceCollector _performanceCollector; private uint? _classJobId = 0; private DateTime _delayedFrameworkUpdateCheck = DateTime.Now; private bool _sentBetweenAreas = false; @@ -41,7 +42,7 @@ public class DalamudUtil : IDisposable } public DalamudUtil(ILogger logger, ClientState clientState, ObjectTable objectTable, Framework framework, - Condition condition, Dalamud.Data.DataManager gameData, MareMediator mediator) + Condition condition, Dalamud.Data.DataManager gameData, MareMediator mediator, PerformanceCollector performanceCollector) { _logger = logger; _clientState = clientState; @@ -49,6 +50,7 @@ public class DalamudUtil : IDisposable _framework = framework; _condition = condition; _mediator = mediator; + _performanceCollector = performanceCollector; _framework.Update += FrameworkOnUpdate; if (IsLoggedIn) { @@ -64,7 +66,12 @@ public class DalamudUtil : IDisposable public Lazy> WorldData { get; private set; } - private unsafe void FrameworkOnUpdate(Framework framework) + private void FrameworkOnUpdate(Framework framework) + { + _performanceCollector.LogPerformance(this, "FrameworkOnUpdate", FrameworkOnUpdateInternal); + } + + private unsafe void FrameworkOnUpdateInternal() { if (GposeTarget != null && !IsInGpose) { @@ -171,9 +178,10 @@ public class DalamudUtil : IDisposable return obj != null && obj.IsValid(); } - public unsafe IntPtr GetMinion() + public unsafe IntPtr GetMinion(IntPtr? playerPointer = null) { - return (IntPtr)((FFXIVClientStructs.FFXIV.Client.Game.Character.Character*)PlayerPointer)->CompanionObject; + playerPointer ??= PlayerPointer; + return (IntPtr)((Character*)playerPointer)->CompanionObject; } public unsafe IntPtr GetPet(IntPtr? playerPointer = null) @@ -190,6 +198,12 @@ public class DalamudUtil : IDisposable return (IntPtr)mgr->LookupBuddyByOwnerObject((BattleChara*)playerPointer); } + public unsafe IntPtr GetMinionOrMount(IntPtr? playerPointer = null) + { + playerPointer ??= PlayerPointer; + return _objectTable.GetObjectAddress(((GameObject*)playerPointer)->ObjectIndex + 1); + } + public string PlayerName => _clientState.LocalPlayer?.Name.ToString() ?? "--"; public uint WorldId => _clientState.LocalPlayer!.HomeWorld.Id; @@ -236,17 +250,6 @@ public class DalamudUtil : IDisposable return null; } - public unsafe IntPtr? GetMinionOrMount(IntPtr chara) - { - var minionOrMount = ((Character*)chara)->CompanionObject; - if (minionOrMount != null) - { - return (IntPtr)minionOrMount; - } - - return null; - } - public async Task RunOnFrameworkThread(Func func) { return await _framework.RunOnFrameworkThread(func).ConfigureAwait(false); @@ -276,11 +279,11 @@ public class DalamudUtil : IDisposable } catch (NullReferenceException ex) { - logger.LogWarning("Error accessing " + handler + ", object does not exist anymore?", ex); + logger.LogWarning(ex, "Error accessing " + handler + ", object does not exist anymore?"); } catch (AccessViolationException ex) { - logger.LogWarning("Error accessing " + handler + ", object does not exist anymore?", ex); + logger.LogWarning(ex, "Error accessing " + handler + ", object does not exist anymore?"); } } diff --git a/MareSynchronos/Utils/PerformanceCollector.cs b/MareSynchronos/Utils/PerformanceCollector.cs new file mode 100644 index 0000000..b23bdbb --- /dev/null +++ b/MareSynchronos/Utils/PerformanceCollector.cs @@ -0,0 +1,168 @@ +using MareSynchronos.MareConfiguration; +using Microsoft.Extensions.Logging; +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Globalization; +using System.Runtime.CompilerServices; +using System.Text; + +namespace MareSynchronos.Utils; + +public class PerformanceCollector +{ + private readonly ConcurrentDictionary>> _performanceCounters = new(StringComparer.Ordinal); + private readonly ILogger _logger; + private readonly MareConfigService _mareConfigService; + private const string counterSplit = "=>"; + + public PerformanceCollector(ILogger logger, MareConfigService mareConfigService) + { + _logger = logger; + _mareConfigService = mareConfigService; + } + + public T LogPerformance(object sender, string counterName, Func func) + { + if (!_mareConfigService.Current.LogPerformance) return func.Invoke(); + + counterName = sender.GetType().Name + counterSplit + counterName; + + if (!_performanceCounters.TryGetValue(counterName, out var list)) + { + list = _performanceCounters[counterName] = new(10000); + } + + Stopwatch st = Stopwatch.StartNew(); + try + { + return func.Invoke(); + } + catch + { + throw; + } + finally + { + st.Stop(); + list.Add(new(TimeOnly.FromDateTime(DateTime.Now), st.ElapsedTicks)); + } + } + + public void LogPerformance(object sender, string counterName, Action act) + { + if (!_mareConfigService.Current.LogPerformance) { act.Invoke(); return; } + + counterName = sender.GetType().Name + counterSplit + counterName; + + if (!_performanceCounters.TryGetValue(counterName, out var list)) + { + list = _performanceCounters[counterName] = new(10000); + } + + Stopwatch st = Stopwatch.StartNew(); + try + { + act.Invoke(); + } + catch + { + throw; + } + finally + { + st.Stop(); + list.Add(new(TimeOnly.FromDateTime(DateTime.Now), st.ElapsedTicks)); + } + + } + + internal void PrintPerformanceStats(int limitBySeconds = 0) + { + if (!_mareConfigService.Current.LogPerformance) + { + _logger.LogWarning("Performance counters are disabled"); + } + + StringBuilder sb = new(); + if (limitBySeconds > 0) + { + sb.AppendLine($"Performance Metrics over the past {limitBySeconds} seconds of each counter"); + } + else + { + sb.AppendLine("Performance metrics over total lifetime of each counter"); + } + var data = _performanceCounters.ToList(); + var longestCounterName = data.OrderByDescending(d => d.Key.Length).First().Key.Length + 2; + sb.Append("-Last".PadRight(15, '-')); + sb.Append('|'); + sb.Append("-Max".PadRight(15, '-')); + sb.Append('|'); + sb.Append("-Average".PadRight(15, '-')); + sb.Append('|'); + sb.Append("-Last Update".PadRight(15, '-')); + sb.Append('|'); + sb.Append("-Entries".PadRight(10, '-')); + sb.Append('|'); + sb.Append("-Counter Name".PadRight(longestCounterName, '-')); + sb.AppendLine(); + var orderedData = data.OrderBy(k => k.Key, StringComparer.OrdinalIgnoreCase).ToList(); + var previousCaller = orderedData.First().Key.Split(counterSplit, StringSplitOptions.RemoveEmptyEntries)[0]; + foreach (var entry in orderedData) + { + var newCaller = entry.Key.Split(counterSplit, StringSplitOptions.RemoveEmptyEntries)[0]; + if (!string.Equals(previousCaller, newCaller, StringComparison.Ordinal)) + { + DrawSeparator(sb, longestCounterName); + } + + var pastEntries = limitBySeconds > 0 ? entry.Value.Where(e => e.Item1.AddMinutes(limitBySeconds / 60.0d) >= TimeOnly.FromDateTime(DateTime.Now)).ToList() : entry.Value.ToList(); + + if (pastEntries.Any()) + { + sb.Append((" " + TimeSpan.FromTicks(pastEntries.LastOrDefault()?.Item2 ?? 0).TotalMilliseconds.ToString("0.00000", CultureInfo.InvariantCulture)).PadRight(15)); + sb.Append('|'); + sb.Append((" " + TimeSpan.FromTicks(pastEntries.Max(m => m.Item2)).TotalMilliseconds.ToString("0.00000", CultureInfo.InvariantCulture)).PadRight(15)); + sb.Append('|'); + sb.Append((" " + TimeSpan.FromTicks((long)pastEntries.Average(m => m.Item2)).TotalMilliseconds.ToString("0.00000", CultureInfo.InvariantCulture)).PadRight(15)); + } + else + { + sb.Append(" -".PadRight(15)); + sb.Append('|'); + sb.Append(" -".PadRight(15)); + sb.Append('|'); + sb.Append(" -".PadRight(15)); + } + sb.Append('|'); + sb.Append((" " + (pastEntries.LastOrDefault()?.Item1.ToString("HH:mm:ss.ffff", CultureInfo.InvariantCulture) ?? "-")).PadRight(15, ' ')); + sb.Append('|'); + sb.Append((" " + pastEntries.Count).PadRight(10)); + sb.Append('|'); + sb.Append(' ').Append(entry.Key); + sb.AppendLine(); + + previousCaller = newCaller; + } + + DrawSeparator(sb, longestCounterName); + + _logger.LogInformation("{perf}", sb.ToString()); + } + + private static void DrawSeparator(StringBuilder sb, int longestCounterName) + { + sb.Append("".PadRight(15, '-')); + sb.Append('+'); + sb.Append("".PadRight(15, '-')); + sb.Append('+'); + sb.Append("".PadRight(15, '-')); + sb.Append('+'); + sb.Append("".PadRight(15, '-')); + sb.Append('+'); + sb.Append("".PadRight(10, '-')); + sb.Append('+'); + sb.Append("".PadRight(longestCounterName, '-')); + sb.AppendLine(); + } +} diff --git a/MareSynchronos/Utils/RollingList.cs b/MareSynchronos/Utils/RollingList.cs new file mode 100644 index 0000000..d97c122 --- /dev/null +++ b/MareSynchronos/Utils/RollingList.cs @@ -0,0 +1,46 @@ +using System.Collections; + +namespace MareSynchronos.Utils; + +public class RollingList : IEnumerable +{ + private readonly LinkedList _list = new(); + private readonly object _addLock = new(); + + public RollingList(int maximumCount) + { + if (maximumCount <= 0) + throw new ArgumentException(message: null, nameof(maximumCount)); + + MaximumCount = maximumCount; + } + + public int MaximumCount { get; } + public int Count => _list.Count; + + public void Add(T value) + { + lock (_addLock) + { + if (_list.Count == MaximumCount) + { + _list.RemoveFirst(); + } + _list.AddLast(value); + } + } + + public T this[int index] + { + get + { + if (index < 0 || index >= Count) + throw new ArgumentOutOfRangeException(nameof(index)); + + return _list.Skip(index).First(); + } + } + + public IEnumerator GetEnumerator() => _list.GetEnumerator(); + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); +} diff --git a/MareSynchronos/WebAPI/ApIController.Functions.Files.cs b/MareSynchronos/WebAPI/ApIController.Functions.Files.cs index b310857..d392c00 100644 --- a/MareSynchronos/WebAPI/ApIController.Functions.Files.cs +++ b/MareSynchronos/WebAPI/ApIController.Functions.Files.cs @@ -21,7 +21,7 @@ public partial class ApiController { private readonly Dictionary _verifiedUploadedHashes; private readonly ConcurrentDictionary _downloadReady = new(); - private bool currentUploadCancelled = false; + private bool _currentUploadCancelled = false; private int _downloadId = 0; public async Task CancelUpload() @@ -148,7 +148,7 @@ public partial class ApiController } catch (HttpRequestException ex) { - _logger.LogWarning($"Error during download of {requestUrl}, HttpStatusCode: {ex.StatusCode}"); + _logger.LogWarning(ex, $"Error during download of {requestUrl}, HttpStatusCode: {ex.StatusCode}"); if (ex.StatusCode is HttpStatusCode.NotFound or HttpStatusCode.Unauthorized) { throw new Exception($"Http error {ex.StatusCode} (cancelled: {ct.IsCancellationRequested}): {requestUrl}", ex); @@ -178,7 +178,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogWarning($"Error during file download of {requestUrl}", ex); + _logger.LogWarning(ex, $"Error during file download of {requestUrl}"); try { if (!tempPath.IsNullOrEmpty()) @@ -235,7 +235,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogCritical("Error during SendRequestInternal for " + requestMessage.RequestUri, ex); + _logger.LogCritical(ex, "Error during SendRequestInternal for " + requestMessage.RequestUri); throw; } } @@ -302,7 +302,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogCritical("Error during download of " + file.Hash, ex); + _logger.LogError(ex, "Error during download of " + file.Hash); return; } @@ -329,9 +329,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogWarning("Issue adding file to the DB"); - _logger.LogWarning(ex.Message); - _logger.LogWarning(ex.StackTrace); + _logger.LogWarning(ex, "Issue creating cache entry"); } } }).ConfigureAwait(false); @@ -346,7 +344,7 @@ public partial class ApiController try { - currentUploadCancelled = await CancelUpload().ConfigureAwait(false); + _currentUploadCancelled = await CancelUpload().ConfigureAwait(false); _uploadCancellationTokenSource = new CancellationTokenSource(); var uploadToken = _uploadCancellationTokenSource.Token; @@ -366,12 +364,12 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogWarning("Error during upload of files", ex); + _logger.LogWarning(ex, "Error during upload of files"); } finally { - if (!currentUploadCancelled) - currentUploadCancelled = await CancelUpload().ConfigureAwait(false); + if (!_currentUploadCancelled) + _currentUploadCancelled = await CancelUpload().ConfigureAwait(false); } } @@ -413,7 +411,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogWarning("Tried to request file " + file.Hash + " but file was not present", ex); + _logger.LogWarning(ex, "Tried to request file " + file.Hash + " but file was not present"); } } diff --git a/MareSynchronos/WebAPI/ApIController.Functions.Users.cs b/MareSynchronos/WebAPI/ApIController.Functions.Users.cs index 05f5b4a..5f52044 100644 --- a/MareSynchronos/WebAPI/ApIController.Functions.Users.cs +++ b/MareSynchronos/WebAPI/ApIController.Functions.Users.cs @@ -22,7 +22,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogWarning("Failed to Push character data: " + ex.Message); + _logger.LogWarning(ex, "Failed to Push character data"); } } diff --git a/MareSynchronos/WebAPI/ApiController.Functions.Callbacks.cs b/MareSynchronos/WebAPI/ApiController.Functions.Callbacks.cs index 14da331..5ea9ec0 100644 --- a/MareSynchronos/WebAPI/ApiController.Functions.Callbacks.cs +++ b/MareSynchronos/WebAPI/ApiController.Functions.Callbacks.cs @@ -19,7 +19,7 @@ public partial class ApiController } catch (Exception ex) { - _logger.LogCritical("Error on executing safely", ex); + _logger.LogCritical(ex, "Error on executing safely"); } } diff --git a/MareSynchronos/WebAPI/ApiController.cs b/MareSynchronos/WebAPI/ApiController.cs index 69c243e..9b13219 100644 --- a/MareSynchronos/WebAPI/ApiController.cs +++ b/MareSynchronos/WebAPI/ApiController.cs @@ -107,7 +107,7 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH get => _serverState; private set { - _logger.LogDebug($"New ServerState: {value}, prev ServerState: {_serverState}"); + _logger.LogDebug("New ServerState: {value}, prev ServerState: {_serverState}", value, _serverState); _serverState = value; } } @@ -209,23 +209,21 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH } catch (HttpRequestException ex) { - _logger.LogWarning("HttpRequestException on Connection", ex); + _logger.LogWarning(ex, "HttpRequestException on Connection"); if (ex.StatusCode == System.Net.HttpStatusCode.Unauthorized) { await StopConnection(token, ServerState.Unauthorized).ConfigureAwait(false); return; } - else - { - ServerState = ServerState.Reconnecting; - _logger.LogInformation("Failed to establish connection, retrying"); - await Task.Delay(TimeSpan.FromSeconds(new Random().Next(5, 20)), token).ConfigureAwait(false); - } + + ServerState = ServerState.Reconnecting; + _logger.LogInformation("Failed to establish connection, retrying"); + await Task.Delay(TimeSpan.FromSeconds(new Random().Next(5, 20)), token).ConfigureAwait(false); } catch (Exception ex) { - _logger.LogWarning("Exception on Connection", ex); + _logger.LogWarning(ex, "Exception on Connection"); _logger.LogInformation("Failed to establish connection, retrying"); await Task.Delay(TimeSpan.FromSeconds(new Random().Next(5, 20)), token).ConfigureAwait(false); @@ -238,7 +236,7 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH while (!ct.IsCancellationRequested && _mareHub != null) { await Task.Delay(TimeSpan.FromSeconds(30), ct).ConfigureAwait(false); - var needsRestart = await CheckClientHealth().ConfigureAwait(false); + _ = await CheckClientHealth().ConfigureAwait(false); _logger.LogDebug("Checked Client Health State"); } } @@ -271,12 +269,12 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH foreach (var userPair in await UserGetPairedClients().ConfigureAwait(false)) { - _logger.LogDebug($"Pair: {userPair}"); + _logger.LogDebug("Individual Pair: {userPair}", userPair); _pairManager.AddUserPair(userPair, addToLastAddedUser: false); } foreach (var entry in await GroupsGetAll().ConfigureAwait(false)) { - _logger.LogDebug($"Group: {entry}"); + _logger.LogDebug("Group: {entry}", entry); _pairManager.AddGroup(entry); } foreach (var group in _pairManager.GroupPairs.Keys) @@ -284,7 +282,7 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH var users = await GroupsGetUsersInGroup(group).ConfigureAwait(false); foreach (var user in users) { - _logger.LogDebug($"GroupPair: {user}"); + _logger.LogDebug("Group Pair: {user}", user); _pairManager.AddGroupPair(user); } } @@ -367,7 +365,7 @@ public partial class ApiController : MediatorSubscriberBase, IDisposable, IMareH _healthCheckTokenSource?.Cancel(); ServerState = ServerState.Reconnecting; Mediator.Publish(new NotificationMessage("Connection lost", "Connection lost to " + _serverManager.CurrentServer!.ServerName, NotificationType.Warning, 5000)); - _logger.LogWarning("Connection closed... Reconnecting", arg); + _logger.LogWarning(arg, "Connection closed... Reconnecting"); return Task.CompletedTask; }