From 048f41244f6b2c7f95ac5bf75be2b16f42b99169 Mon Sep 17 00:00:00 2001 From: Jesse Plamondon-Willard Date: Sun, 15 May 2022 01:54:01 -0400 Subject: reduce performance impact of deprecation warnings Creating a stack is *very* slow, so it should be avoided if possible until after the duplicate-warning check. --- src/SMAPI/Constants.cs | 2 +- src/SMAPI/Context.cs | 5 +++ src/SMAPI/Framework/Content/AssetInfo.cs | 4 +-- .../Framework/Content/AssetInterceptorChange.cs | 10 ++++++ src/SMAPI/Framework/ContentCoordinator.cs | 18 ++++++---- .../ContentManagers/GameContentManager.cs | 12 ++++++- .../Framework/Deprecations/DeprecationManager.cs | 41 ++++++++++++++-------- src/SMAPI/Framework/Events/ManagedEvent.cs | 12 +++++++ src/SMAPI/Framework/ModHelpers/CommandHelper.cs | 2 +- src/SMAPI/Framework/ModHelpers/ModHelper.cs | 2 +- src/SMAPI/Framework/ModRegistry.cs | 9 ++--- src/SMAPI/Framework/SCore.cs | 18 ++++++++-- src/SMAPI/Utilities/PerScreen.cs | 2 +- 13 files changed, 100 insertions(+), 37 deletions(-) (limited to 'src') diff --git a/src/SMAPI/Constants.cs b/src/SMAPI/Constants.cs index ef729f4f..6c9a56cc 100644 --- a/src/SMAPI/Constants.cs +++ b/src/SMAPI/Constants.cs @@ -84,7 +84,7 @@ namespace StardewModdingAPI get { SCore.DeprecationManager.Warn( - source: SCore.DeprecationManager.GetModFromStack(), + source: null, nounPhrase: $"{nameof(Constants)}.{nameof(Constants.ExecutionPath)}", version: "3.14.0", severity: DeprecationLevel.Notice diff --git a/src/SMAPI/Context.cs b/src/SMAPI/Context.cs index aa4ecf35..c822908e 100644 --- a/src/SMAPI/Context.cs +++ b/src/SMAPI/Context.cs @@ -1,6 +1,7 @@ using System.Collections.Generic; using StardewModdingAPI.Enums; using StardewModdingAPI.Events; +using StardewModdingAPI.Framework; using StardewModdingAPI.Utilities; using StardewValley; using StardewValley.Menus; @@ -41,6 +42,10 @@ namespace StardewModdingAPI /// Whether the in-game world is completely unloaded and not in the process of being loaded. The world may still exist in memory at this point, but should be ignored. internal static bool IsWorldFullyUnloaded => Context.LoadStage is LoadStage.ReturningToTitle or LoadStage.None; + /// If SMAPI is currently waiting for mod code, the mods to which it belongs (with the most recent at the top of the stack). + /// This is heuristic only. It provides a quick way to identify the most likely mod for deprecation warnings, but it should be followed with a more accurate check if needed. + internal static Stack HeuristicModsRunningCode { get; } = new(); + /********* ** Accessors diff --git a/src/SMAPI/Framework/Content/AssetInfo.cs b/src/SMAPI/Framework/Content/AssetInfo.cs index a4f0a408..773e3126 100644 --- a/src/SMAPI/Framework/Content/AssetInfo.cs +++ b/src/SMAPI/Framework/Content/AssetInfo.cs @@ -36,7 +36,7 @@ namespace StardewModdingAPI.Framework.Content get { SCore.DeprecationManager.Warn( - source: SCore.DeprecationManager.GetModFromStack(), + source: null, nounPhrase: $"{nameof(IAssetInfo)}.{nameof(IAssetInfo.AssetName)}", version: "3.14.0", severity: DeprecationLevel.Notice, @@ -76,7 +76,7 @@ namespace StardewModdingAPI.Framework.Content public bool AssetNameEquals(string path) { SCore.DeprecationManager.Warn( - source: SCore.DeprecationManager.GetModFromStack(), + source: null, nounPhrase: $"{nameof(IAssetInfo)}.{nameof(IAssetInfo.AssetNameEquals)}", version: "3.14.0", severity: DeprecationLevel.Notice, diff --git a/src/SMAPI/Framework/Content/AssetInterceptorChange.cs b/src/SMAPI/Framework/Content/AssetInterceptorChange.cs index fc8199e8..f3d4f3f4 100644 --- a/src/SMAPI/Framework/Content/AssetInterceptorChange.cs +++ b/src/SMAPI/Framework/Content/AssetInterceptorChange.cs @@ -64,6 +64,7 @@ namespace StardewModdingAPI.Framework.Content // check edit if (this.Instance is IAssetEditor editor) { + Context.HeuristicModsRunningCode.Push(this.Mod); try { if (editor.CanEdit(asset)) @@ -73,11 +74,16 @@ namespace StardewModdingAPI.Framework.Content { this.Mod.LogAsMod($"Mod failed when checking whether it could edit asset '{asset.Name}'. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } } // check load if (this.Instance is IAssetLoader loader) { + Context.HeuristicModsRunningCode.Push(this.Mod); try { if (loader.CanLoad(asset)) @@ -87,6 +93,10 @@ namespace StardewModdingAPI.Framework.Content { this.Mod.LogAsMod($"Mod failed when checking whether it could load asset '{asset.Name}'. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } } return false; diff --git a/src/SMAPI/Framework/ContentCoordinator.cs b/src/SMAPI/Framework/ContentCoordinator.cs index a24581a0..2b13f57a 100644 --- a/src/SMAPI/Framework/ContentCoordinator.cs +++ b/src/SMAPI/Framework/ContentCoordinator.cs @@ -595,6 +595,7 @@ namespace StardewModdingAPI.Framework foreach (ModLinked loader in this.Loaders) { // check if loader applies + Context.HeuristicModsRunningCode.Push(loader.Mod); try { if (!loader.Data.CanLoad(legacyInfo)) @@ -605,6 +606,10 @@ namespace StardewModdingAPI.Framework loader.Mod.LogAsMod($"Mod failed when checking whether it could load asset '{legacyInfo.Name}', and will be ignored. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); continue; } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } // add operation group ??= new AssetOperationGroup(new List(), new List()); @@ -617,9 +622,7 @@ namespace StardewModdingAPI.Framework Mod: loader.Mod, OnBehalfOf: null, Priority: AssetLoadPriority.Exclusive, - GetData: assetInfo => loader.Data.Load( - this.GetLegacyAssetInfo(assetInfo) - ) + GetData: assetInfo => loader.Data.Load(this.GetLegacyAssetInfo(assetInfo)) ) ) ); @@ -629,6 +632,7 @@ namespace StardewModdingAPI.Framework foreach (var editor in this.Editors) { // check if editor applies + Context.HeuristicModsRunningCode.Push(editor.Mod); try { if (!editor.Data.CanEdit(legacyInfo)) @@ -639,6 +643,10 @@ namespace StardewModdingAPI.Framework editor.Mod.LogAsMod($"Mod crashed when checking whether it could edit asset '{legacyInfo.Name}', and will be ignored. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); continue; } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } // HACK // @@ -672,9 +680,7 @@ namespace StardewModdingAPI.Framework Mod: editor.Mod, OnBehalfOf: null, Priority: priority, - ApplyEdit: assetData => editor.Data.Edit( - this.GetLegacyAssetData(assetData) - ) + ApplyEdit: assetData => editor.Data.Edit(this.GetLegacyAssetData(assetData)) ) ) ); diff --git a/src/SMAPI/Framework/ContentManagers/GameContentManager.cs b/src/SMAPI/Framework/ContentManagers/GameContentManager.cs index 2aa50542..1c603f85 100644 --- a/src/SMAPI/Framework/ContentManagers/GameContentManager.cs +++ b/src/SMAPI/Framework/ContentManagers/GameContentManager.cs @@ -177,6 +177,7 @@ namespace StardewModdingAPI.Framework.ContentManagers // fetch asset from loader IModMetadata mod = loader.Mod; T data; + Context.HeuristicModsRunningCode.Push(loader.Mod); try { data = (T)loader.GetData(info); @@ -187,6 +188,10 @@ namespace StardewModdingAPI.Framework.ContentManagers mod.LogAsMod($"Mod crashed when loading asset '{info.Name}'{this.GetOnBehalfOfLabel(loader.OnBehalfOf)}. SMAPI will use the default asset instead. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); return null; } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } // return matched asset return this.TryFixAndValidateLoadedAsset(info, data, loader) @@ -229,6 +234,7 @@ namespace StardewModdingAPI.Framework.ContentManagers // try edit object prevAsset = asset.Data; + Context.HeuristicModsRunningCode.Push(editor.Mod); try { editor.ApplyEdit(asset); @@ -238,9 +244,13 @@ namespace StardewModdingAPI.Framework.ContentManagers { mod.LogAsMod($"Mod crashed when editing asset '{info.Name}'{this.GetOnBehalfOfLabel(editor.OnBehalfOf)}, which may cause errors in-game. Error details:\n{ex.GetLogSummary()}", LogLevel.Error); } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } // validate edit - // ReSharper disable once ConditionIsAlwaysTrueOrFalse -- it's only guaranteed non-null after this method + // ReSharper disable once ConditionIsAlwaysTrueOrFalseAccordingToNullableAPIContract -- it's only guaranteed non-null after this method if (asset.Data == null) { mod.LogAsMod($"Mod incorrectly set asset '{info.Name}'{this.GetOnBehalfOfLabel(editor.OnBehalfOf)} to a null value; ignoring override.", LogLevel.Warn); diff --git a/src/SMAPI/Framework/Deprecations/DeprecationManager.cs b/src/SMAPI/Framework/Deprecations/DeprecationManager.cs index 288abde2..3bbbd7b8 100644 --- a/src/SMAPI/Framework/Deprecations/DeprecationManager.cs +++ b/src/SMAPI/Framework/Deprecations/DeprecationManager.cs @@ -37,13 +37,6 @@ namespace StardewModdingAPI.Framework.Deprecations this.ModRegistry = modRegistry; } - /// Get a mod for the closest assembly registered as a source of deprecation warnings. - /// Returns the source name, or null if no registered assemblies were found. - public IModMetadata? GetModFromStack() - { - return this.ModRegistry.GetFromStack(); - } - /// Get a mod from its unique ID. /// The mod's unique ID. public IModMetadata? GetMod(string modId) @@ -52,7 +45,7 @@ namespace StardewModdingAPI.Framework.Deprecations } /// Log a deprecation warning. - /// The mod which used the deprecated code, if known. + /// The mod which used the deprecated code, or null to get it heuristically. Note that getting it heuristically is very slow in some cases, and should be avoided if at all possible. /// A noun phrase describing what is deprecated. /// The SMAPI version which deprecated it. /// How deprecated the code is. @@ -60,18 +53,38 @@ namespace StardewModdingAPI.Framework.Deprecations /// Whether to log a stack trace showing where the deprecated code is in the mod. public void Warn(IModMetadata? source, string nounPhrase, string version, DeprecationLevel severity, string[]? unlessStackIncludes = null, bool logStackTrace = true) { + // get heuristic source + // The call stack is usually the most reliable way to get the source if it's unknown. This is *very* slow + // though, especially before we check whether this is a duplicate warning. The initial cache check uses a + // quick heuristic method if at all possible to avoid that. + IModMetadata? heuristicSource = source; + ImmutableStackTrace? stack = null; + if (heuristicSource is null) + Context.HeuristicModsRunningCode.TryPeek(out heuristicSource); + if (heuristicSource is null) + { + stack = ImmutableStackTrace.Get(skipFrames: 1); + heuristicSource = this.ModRegistry.GetFromStack(stack.GetFrames()); + } + // skip if already warned - string cacheKey = $"{source?.DisplayName ?? ""}::{nounPhrase}::{version}"; + string cacheKey = $"{heuristicSource?.Manifest.UniqueID ?? ""}::{nounPhrase}::{version}"; if (this.LoggedDeprecations.Contains(cacheKey)) return; + this.LoggedDeprecations.Add(cacheKey); - // warn if valid - ImmutableStackTrace stack = ImmutableStackTrace.Get(skipFrames: 1); - if (!this.ShouldSuppress(stack, unlessStackIncludes)) + // get more accurate source + if (stack is not null) + source ??= heuristicSource!; + else { - this.LoggedDeprecations.Add(cacheKey); - this.QueuedWarnings.Add(new DeprecationWarning(source, nounPhrase, version, severity, stack, logStackTrace)); + stack ??= ImmutableStackTrace.Get(skipFrames: 1); + source ??= this.ModRegistry.GetFromStack(stack.GetFrames()); } + + // log unless suppressed + if (!this.ShouldSuppress(stack, unlessStackIncludes)) + this.QueuedWarnings.Add(new DeprecationWarning(source, nounPhrase, version, severity, stack, logStackTrace)); } /// A placeholder method used to track deprecated code for which a separate warning will be shown. diff --git a/src/SMAPI/Framework/Events/ManagedEvent.cs b/src/SMAPI/Framework/Events/ManagedEvent.cs index 8a3ca839..a72d8d04 100644 --- a/src/SMAPI/Framework/Events/ManagedEvent.cs +++ b/src/SMAPI/Framework/Events/ManagedEvent.cs @@ -104,6 +104,8 @@ namespace StardewModdingAPI.Framework.Events // raise event foreach (ManagedEventHandler handler in this.GetHandlers()) { + Context.HeuristicModsRunningCode.Push(handler.SourceMod); + try { handler.Handler(null, args); @@ -112,6 +114,10 @@ namespace StardewModdingAPI.Framework.Events { this.LogError(handler, ex); } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } } } @@ -126,6 +132,8 @@ namespace StardewModdingAPI.Framework.Events // raise event foreach (ManagedEventHandler handler in this.GetHandlers()) { + Context.HeuristicModsRunningCode.Push(handler.SourceMod); + try { invoke(handler.SourceMod, args => handler.Handler(null, args)); @@ -134,6 +142,10 @@ namespace StardewModdingAPI.Framework.Events { this.LogError(handler, ex); } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } } } diff --git a/src/SMAPI/Framework/ModHelpers/CommandHelper.cs b/src/SMAPI/Framework/ModHelpers/CommandHelper.cs index f39ed42e..ddbd618a 100644 --- a/src/SMAPI/Framework/ModHelpers/CommandHelper.cs +++ b/src/SMAPI/Framework/ModHelpers/CommandHelper.cs @@ -37,7 +37,7 @@ namespace StardewModdingAPI.Framework.ModHelpers public bool Trigger(string name, string[] arguments) { SCore.DeprecationManager.Warn( - source: SCore.DeprecationManager.GetMod(this.ModID), + source: this.Mod, nounPhrase: $"{nameof(IModHelper)}.{nameof(IModHelper.ConsoleCommands)}.{nameof(ICommandHelper.Trigger)}", version: "3.8.1", severity: DeprecationLevel.Notice diff --git a/src/SMAPI/Framework/ModHelpers/ModHelper.cs b/src/SMAPI/Framework/ModHelpers/ModHelper.cs index 008195d9..48973691 100644 --- a/src/SMAPI/Framework/ModHelpers/ModHelper.cs +++ b/src/SMAPI/Framework/ModHelpers/ModHelper.cs @@ -33,7 +33,7 @@ namespace StardewModdingAPI.Framework.ModHelpers get { SCore.DeprecationManager.Warn( - source: SCore.DeprecationManager.GetMod(this.ModID), + source: this.Mod, nounPhrase: $"{nameof(IModHelper)}.{nameof(IModHelper.Content)}", version: "3.14.0", severity: DeprecationLevel.Notice diff --git a/src/SMAPI/Framework/ModRegistry.cs b/src/SMAPI/Framework/ModRegistry.cs index 1ae5643f..1b0a076f 100644 --- a/src/SMAPI/Framework/ModRegistry.cs +++ b/src/SMAPI/Framework/ModRegistry.cs @@ -99,14 +99,10 @@ namespace StardewModdingAPI.Framework } /// Get the mod metadata from the closest assembly registered as a source of deprecation warnings. + /// The call stack to analyze. /// Returns the mod's metadata, or null if no registered assemblies were found. - public IModMetadata? GetFromStack() + public IModMetadata? GetFromStack(StackFrame[] frames) { - // get stack frames - StackTrace stack = new(); - StackFrame[] frames = stack.GetFrames(); - - // search stack for a source assembly foreach (StackFrame frame in frames) { IModMetadata? mod = this.GetFrom(frame); @@ -114,7 +110,6 @@ namespace StardewModdingAPI.Framework return mod; } - // no known assembly found return null; } } diff --git a/src/SMAPI/Framework/SCore.cs b/src/SMAPI/Framework/SCore.cs index 5ae4fdbb..7042e83a 100644 --- a/src/SMAPI/Framework/SCore.cs +++ b/src/SMAPI/Framework/SCore.cs @@ -1677,6 +1677,7 @@ namespace StardewModdingAPI.Framework #pragma warning restore CS0612, CS0618 // call entry method + Context.HeuristicModsRunningCode.Push(metadata); try { IMod mod = metadata.Mod!; @@ -1705,6 +1706,7 @@ namespace StardewModdingAPI.Framework { this.Monitor.Log($"Failed loading mod-provided API for {metadata.DisplayName}. Integrations with other mods may not work. Error: {ex.GetLogSummary()}", LogLevel.Error); } + Context.HeuristicModsRunningCode.TryPop(out _); } // unlock mod integrations @@ -1852,7 +1854,7 @@ namespace StardewModdingAPI.Framework try { // get mod instance - if (!this.TryLoadModEntry(modAssembly, out Mod? modEntry, out errorReasonPhrase)) + if (!this.TryLoadModEntry(mod, modAssembly, out Mod? modEntry, out errorReasonPhrase)) { failReason = ModFailReason.LoadFailed; return false; @@ -1954,11 +1956,12 @@ namespace StardewModdingAPI.Framework } /// Load a mod's entry class. + /// The mod metadata whose entry class is being loaded. /// The mod assembly. /// The loaded instance. /// The error indicating why loading failed (if applicable). /// Returns whether the mod entry class was successfully loaded. - private bool TryLoadModEntry(Assembly modAssembly, [NotNullWhen(true)] out Mod? mod, [NotNullWhen(false)] out string? error) + private bool TryLoadModEntry(IModMetadata metadata, Assembly modAssembly, [NotNullWhen(true)] out Mod? mod, [NotNullWhen(false)] out string? error) { mod = null; @@ -1976,7 +1979,16 @@ namespace StardewModdingAPI.Framework } // get implementation - mod = (Mod?)modAssembly.CreateInstance(modEntries[0].ToString()); + Context.HeuristicModsRunningCode.Push(metadata); + try + { + mod = (Mod?)modAssembly.CreateInstance(modEntries[0].ToString()); + } + finally + { + Context.HeuristicModsRunningCode.TryPop(out _); + } + if (mod == null) { error = "its entry class couldn't be instantiated."; diff --git a/src/SMAPI/Utilities/PerScreen.cs b/src/SMAPI/Utilities/PerScreen.cs index 1c4c56fe..b86310b8 100644 --- a/src/SMAPI/Utilities/PerScreen.cs +++ b/src/SMAPI/Utilities/PerScreen.cs @@ -97,7 +97,7 @@ namespace StardewModdingAPI.Utilities if (!nullExpected) { SCore.DeprecationManager.Warn( - SCore.DeprecationManager.GetModFromStack(), + null, $"calling the {nameof(PerScreen)} constructor with null", "3.14.0", DeprecationLevel.Notice -- cgit