diff options
Diffstat (limited to 'src/SMAPI/Framework')
| -rw-r--r-- | src/SMAPI/Framework/Events/EventManager.cs | 48 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Events/IManagedEvent.cs | 15 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Events/ManagedEvent.cs | 58 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/AlertContext.cs | 34 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/AlertEntry.cs | 38 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/PeakEntry.cs | 35 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounter.cs | 125 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterCollection.cs | 205 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterEntry.cs | 30 | ||||
| -rw-r--r-- | src/SMAPI/Framework/PerformanceMonitoring/PerformanceMonitor.cs | 184 | ||||
| -rw-r--r-- | src/SMAPI/Framework/SCore.cs | 14 | ||||
| -rw-r--r-- | src/SMAPI/Framework/SGame.cs | 11 |
12 files changed, 763 insertions, 34 deletions
diff --git a/src/SMAPI/Framework/Events/EventManager.cs b/src/SMAPI/Framework/Events/EventManager.cs index 892cbc7b..a9dfda97 100644 --- a/src/SMAPI/Framework/Events/EventManager.cs +++ b/src/SMAPI/Framework/Events/EventManager.cs @@ -1,5 +1,8 @@ +using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; +using System.Reflection; using StardewModdingAPI.Events; +using StardewModdingAPI.Framework.PerformanceMonitoring; namespace StardewModdingAPI.Framework.Events { @@ -173,28 +176,32 @@ namespace StardewModdingAPI.Framework.Events /// <summary>Construct an instance.</summary> /// <param name="monitor">Writes messages to the log.</param> /// <param name="modRegistry">The mod registry with which to identify mods.</param> - public EventManager(IMonitor monitor, ModRegistry modRegistry) + /// <param name="performanceMonitor">Tracks performance metrics.</param> + public EventManager(IMonitor monitor, ModRegistry modRegistry, PerformanceMonitor performanceMonitor) { // create shortcut initializers - ManagedEvent<TEventArgs> ManageEventOf<TEventArgs>(string typeName, string eventName) => new ManagedEvent<TEventArgs>($"{typeName}.{eventName}", monitor, modRegistry); + ManagedEvent<TEventArgs> ManageEventOf<TEventArgs>(string typeName, string eventName, bool isPerformanceCritical = false) + { + return new ManagedEvent<TEventArgs>($"{typeName}.{eventName}", monitor, modRegistry, performanceMonitor, isPerformanceCritical); + } // init events (new) this.MenuChanged = ManageEventOf<MenuChangedEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.MenuChanged)); - this.Rendering = ManageEventOf<RenderingEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.Rendering)); - this.Rendered = ManageEventOf<RenderedEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.Rendered)); - this.RenderingWorld = ManageEventOf<RenderingWorldEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingWorld)); - this.RenderedWorld = ManageEventOf<RenderedWorldEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedWorld)); - this.RenderingActiveMenu = ManageEventOf<RenderingActiveMenuEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingActiveMenu)); - this.RenderedActiveMenu = ManageEventOf<RenderedActiveMenuEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedActiveMenu)); - this.RenderingHud = ManageEventOf<RenderingHudEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingHud)); - this.RenderedHud = ManageEventOf<RenderedHudEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedHud)); + this.Rendering = ManageEventOf<RenderingEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.Rendering), isPerformanceCritical: true); + this.Rendered = ManageEventOf<RenderedEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.Rendered), isPerformanceCritical: true); + this.RenderingWorld = ManageEventOf<RenderingWorldEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingWorld), isPerformanceCritical: true); + this.RenderedWorld = ManageEventOf<RenderedWorldEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedWorld), isPerformanceCritical: true); + this.RenderingActiveMenu = ManageEventOf<RenderingActiveMenuEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingActiveMenu), isPerformanceCritical: true); + this.RenderedActiveMenu = ManageEventOf<RenderedActiveMenuEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedActiveMenu), isPerformanceCritical: true); + this.RenderingHud = ManageEventOf<RenderingHudEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderingHud), isPerformanceCritical: true); + this.RenderedHud = ManageEventOf<RenderedHudEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.RenderedHud), isPerformanceCritical: true); this.WindowResized = ManageEventOf<WindowResizedEventArgs>(nameof(IModEvents.Display), nameof(IDisplayEvents.WindowResized)); this.GameLaunched = ManageEventOf<GameLaunchedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.GameLaunched)); - this.UpdateTicking = ManageEventOf<UpdateTickingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.UpdateTicking)); - this.UpdateTicked = ManageEventOf<UpdateTickedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.UpdateTicked)); - this.OneSecondUpdateTicking = ManageEventOf<OneSecondUpdateTickingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.OneSecondUpdateTicking)); - this.OneSecondUpdateTicked = ManageEventOf<OneSecondUpdateTickedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.OneSecondUpdateTicked)); + this.UpdateTicking = ManageEventOf<UpdateTickingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.UpdateTicking), isPerformanceCritical: true); + this.UpdateTicked = ManageEventOf<UpdateTickedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.UpdateTicked), isPerformanceCritical: true); + this.OneSecondUpdateTicking = ManageEventOf<OneSecondUpdateTickingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.OneSecondUpdateTicking), isPerformanceCritical: true); + this.OneSecondUpdateTicked = ManageEventOf<OneSecondUpdateTickedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.OneSecondUpdateTicked), isPerformanceCritical: true); this.SaveCreating = ManageEventOf<SaveCreatingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.SaveCreating)); this.SaveCreated = ManageEventOf<SaveCreatedEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.SaveCreated)); this.Saving = ManageEventOf<SavingEventArgs>(nameof(IModEvents.GameLoop), nameof(IGameLoopEvents.Saving)); @@ -207,7 +214,7 @@ namespace StardewModdingAPI.Framework.Events this.ButtonPressed = ManageEventOf<ButtonPressedEventArgs>(nameof(IModEvents.Input), nameof(IInputEvents.ButtonPressed)); this.ButtonReleased = ManageEventOf<ButtonReleasedEventArgs>(nameof(IModEvents.Input), nameof(IInputEvents.ButtonReleased)); - this.CursorMoved = ManageEventOf<CursorMovedEventArgs>(nameof(IModEvents.Input), nameof(IInputEvents.CursorMoved)); + this.CursorMoved = ManageEventOf<CursorMovedEventArgs>(nameof(IModEvents.Input), nameof(IInputEvents.CursorMoved), isPerformanceCritical: true); this.MouseWheelScrolled = ManageEventOf<MouseWheelScrolledEventArgs>(nameof(IModEvents.Input), nameof(IInputEvents.MouseWheelScrolled)); this.PeerContextReceived = ManageEventOf<PeerContextReceivedEventArgs>(nameof(IModEvents.Multiplayer), nameof(IMultiplayerEvents.PeerContextReceived)); @@ -228,8 +235,15 @@ namespace StardewModdingAPI.Framework.Events this.TerrainFeatureListChanged = ManageEventOf<TerrainFeatureListChangedEventArgs>(nameof(IModEvents.World), nameof(IWorldEvents.TerrainFeatureListChanged)); this.LoadStageChanged = ManageEventOf<LoadStageChangedEventArgs>(nameof(IModEvents.Specialized), nameof(ISpecializedEvents.LoadStageChanged)); - this.UnvalidatedUpdateTicking = ManageEventOf<UnvalidatedUpdateTickingEventArgs>(nameof(IModEvents.Specialized), nameof(ISpecializedEvents.UnvalidatedUpdateTicking)); - this.UnvalidatedUpdateTicked = ManageEventOf<UnvalidatedUpdateTickedEventArgs>(nameof(IModEvents.Specialized), nameof(ISpecializedEvents.UnvalidatedUpdateTicked)); + this.UnvalidatedUpdateTicking = ManageEventOf<UnvalidatedUpdateTickingEventArgs>(nameof(IModEvents.Specialized), nameof(ISpecializedEvents.UnvalidatedUpdateTicking), isPerformanceCritical: true); + this.UnvalidatedUpdateTicked = ManageEventOf<UnvalidatedUpdateTickedEventArgs>(nameof(IModEvents.Specialized), nameof(ISpecializedEvents.UnvalidatedUpdateTicked), isPerformanceCritical: true); + } + + /// <summary>Get all managed events.</summary> + public IEnumerable<IManagedEvent> GetAllEvents() + { + foreach (FieldInfo field in this.GetType().GetFields()) + yield return (IManagedEvent)field.GetValue(this); } } } diff --git a/src/SMAPI/Framework/Events/IManagedEvent.cs b/src/SMAPI/Framework/Events/IManagedEvent.cs new file mode 100644 index 00000000..e4e3ca08 --- /dev/null +++ b/src/SMAPI/Framework/Events/IManagedEvent.cs @@ -0,0 +1,15 @@ +namespace StardewModdingAPI.Framework.Events +{ + /// <summary>Metadata for an event raised by SMAPI.</summary> + internal interface IManagedEvent + { + /********* + ** Accessors + *********/ + /// <summary>A human-readable name for the event.</summary> + string EventName { get; } + + /// <summary>Whether the event is typically called at least once per second.</summary> + bool IsPerformanceCritical { get; } + } +} diff --git a/src/SMAPI/Framework/Events/ManagedEvent.cs b/src/SMAPI/Framework/Events/ManagedEvent.cs index 2afe7a03..118b73ac 100644 --- a/src/SMAPI/Framework/Events/ManagedEvent.cs +++ b/src/SMAPI/Framework/Events/ManagedEvent.cs @@ -1,12 +1,13 @@ using System; using System.Collections.Generic; using System.Linq; +using StardewModdingAPI.Framework.PerformanceMonitoring; namespace StardewModdingAPI.Framework.Events { /// <summary>An event wrapper which intercepts and logs errors in handler code.</summary> /// <typeparam name="TEventArgs">The event arguments type.</typeparam> - internal class ManagedEvent<TEventArgs> + internal class ManagedEvent<TEventArgs> : IManagedEvent { /********* ** Fields @@ -14,9 +15,6 @@ namespace StardewModdingAPI.Framework.Events /// <summary>The underlying event.</summary> private event EventHandler<TEventArgs> Event; - /// <summary>A human-readable name for the event.</summary> - private readonly string EventName; - /// <summary>Writes messages to the log.</summary> private readonly IMonitor Monitor; @@ -29,6 +27,19 @@ namespace StardewModdingAPI.Framework.Events /// <summary>The cached invocation list.</summary> private EventHandler<TEventArgs>[] CachedInvocationList; + /// <summary>Tracks performance metrics.</summary> + private readonly PerformanceMonitor PerformanceMonitor; + + + /********* + ** Accessors + *********/ + /// <summary>A human-readable name for the event.</summary> + public string EventName { get; } + + /// <summary>Whether the event is typically called at least once per second.</summary> + public bool IsPerformanceCritical { get; } + /********* ** Public methods @@ -37,11 +48,15 @@ namespace StardewModdingAPI.Framework.Events /// <param name="eventName">A human-readable name for the event.</param> /// <param name="monitor">Writes messages to the log.</param> /// <param name="modRegistry">The mod registry with which to identify mods.</param> - public ManagedEvent(string eventName, IMonitor monitor, ModRegistry modRegistry) + /// <param name="performanceMonitor">Tracks performance metrics.</param> + /// <param name="isPerformanceCritical">Whether the event is typically called at least once per second.</param> + public ManagedEvent(string eventName, IMonitor monitor, ModRegistry modRegistry, PerformanceMonitor performanceMonitor, bool isPerformanceCritical = false) { this.EventName = eventName; this.Monitor = monitor; this.ModRegistry = modRegistry; + this.PerformanceMonitor = performanceMonitor; + this.IsPerformanceCritical = isPerformanceCritical; } /// <summary>Get whether anything is listening to the event.</summary> @@ -81,17 +96,21 @@ namespace StardewModdingAPI.Framework.Events if (this.Event == null) return; - foreach (EventHandler<TEventArgs> handler in this.CachedInvocationList) + + this.PerformanceMonitor.Track(this.EventName, () => { - try + foreach (EventHandler<TEventArgs> handler in this.CachedInvocationList) { - handler.Invoke(null, args); - } - catch (Exception ex) - { - this.LogError(handler, ex); + try + { + this.PerformanceMonitor.Track(this.EventName, this.GetModNameForPerformanceCounters(handler), () => handler.Invoke(null, args)); + } + catch (Exception ex) + { + this.LogError(handler, ex); + } } - } + }); } /// <summary>Raise the event and notify all handlers.</summary> @@ -122,6 +141,19 @@ namespace StardewModdingAPI.Framework.Events /********* ** Private methods *********/ + /// <summary>Get the mod name for a given event handler to display in performance monitoring reports.</summary> + /// <param name="handler">The event handler.</param> + private string GetModNameForPerformanceCounters(EventHandler<TEventArgs> handler) + { + IModMetadata mod = this.GetSourceMod(handler); + if (mod == null) + return Constants.GamePerformanceCounterName; + + return mod.HasManifest() + ? mod.Manifest.UniqueID + : mod.DisplayName; + } + /// <summary>Track an event handler.</summary> /// <param name="mod">The mod which added the handler.</param> /// <param name="handler">The event handler.</param> diff --git a/src/SMAPI/Framework/PerformanceMonitoring/AlertContext.cs b/src/SMAPI/Framework/PerformanceMonitoring/AlertContext.cs new file mode 100644 index 00000000..01197f74 --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/AlertContext.cs @@ -0,0 +1,34 @@ +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>The context for an alert.</summary> + internal struct AlertContext + { + /********* + ** Accessors + *********/ + /// <summary>The source which triggered the alert.</summary> + public string Source { get; } + + /// <summary>The elapsed milliseconds.</summary> + public double Elapsed { get; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="source">The source which triggered the alert.</param> + /// <param name="elapsed">The elapsed milliseconds.</param> + public AlertContext(string source, double elapsed) + { + this.Source = source; + this.Elapsed = elapsed; + } + + /// <summary>Get a human-readable text form of this instance.</summary> + public override string ToString() + { + return $"{this.Source}: {this.Elapsed:F2}ms"; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/AlertEntry.cs b/src/SMAPI/Framework/PerformanceMonitoring/AlertEntry.cs new file mode 100644 index 00000000..f5b80189 --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/AlertEntry.cs @@ -0,0 +1,38 @@ +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>A single alert entry.</summary> + internal struct AlertEntry + { + /********* + ** Accessors + *********/ + /// <summary>The collection in which the alert occurred.</summary> + public PerformanceCounterCollection Collection { get; } + + /// <summary>The actual execution time in milliseconds.</summary> + public double ExecutionTimeMilliseconds { get; } + + /// <summary>The configured alert threshold in milliseconds.</summary> + public double ThresholdMilliseconds { get; } + + /// <summary>The sources involved in exceeding the threshold.</summary> + public AlertContext[] Context { get; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="collection">The collection in which the alert occurred.</param> + /// <param name="executionTimeMilliseconds">The actual execution time in milliseconds.</param> + /// <param name="thresholdMilliseconds">The configured alert threshold in milliseconds.</param> + /// <param name="context">The sources involved in exceeding the threshold.</param> + public AlertEntry(PerformanceCounterCollection collection, double executionTimeMilliseconds, double thresholdMilliseconds, AlertContext[] context) + { + this.Collection = collection; + this.ExecutionTimeMilliseconds = executionTimeMilliseconds; + this.ThresholdMilliseconds = thresholdMilliseconds; + this.Context = context; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/PeakEntry.cs b/src/SMAPI/Framework/PerformanceMonitoring/PeakEntry.cs new file mode 100644 index 00000000..cff502ad --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/PeakEntry.cs @@ -0,0 +1,35 @@ +using System; + +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>A peak invocation time.</summary> + internal struct PeakEntry + { + /********* + ** Accessors + *********/ + /// <summary>The actual execution time in milliseconds.</summary> + public double ExecutionTimeMilliseconds { get; } + + /// <summary>When the entry occurred.</summary> + public DateTime EventTime { get; } + + /// <summary>The sources involved in exceeding the threshold.</summary> + public AlertContext[] Context { get; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="executionTimeMilliseconds">The actual execution time in milliseconds.</param> + /// <param name="eventTime">When the entry occurred.</param> + /// <param name="context">The sources involved in exceeding the threshold.</param> + public PeakEntry(double executionTimeMilliseconds, DateTime eventTime, AlertContext[] context) + { + this.ExecutionTimeMilliseconds = executionTimeMilliseconds; + this.EventTime = eventTime; + this.Context = context; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounter.cs b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounter.cs new file mode 100644 index 00000000..3cf668ee --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounter.cs @@ -0,0 +1,125 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using Harmony; + +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>Tracks metadata about a particular code event.</summary> + internal class PerformanceCounter + { + /********* + ** Fields + *********/ + /// <summary>The size of the ring buffer.</summary> + private readonly int MaxEntries = 16384; + + /// <summary>The collection to which this performance counter belongs.</summary> + private readonly PerformanceCounterCollection ParentCollection; + + /// <summary>The performance counter entries.</summary> + private readonly Stack<PerformanceCounterEntry> Entries; + + /// <summary>The entry with the highest execution time.</summary> + private PerformanceCounterEntry? PeakPerformanceCounterEntry; + + + /********* + ** Accessors + *********/ + /// <summary>The name of the source.</summary> + public string Source { get; } + + /// <summary>The alert threshold in milliseconds</summary> + public double AlertThresholdMilliseconds { get; set; } + + /// <summary>If alerting is enabled or not</summary> + public bool EnableAlerts { get; set; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="parentCollection">The collection to which this performance counter belongs.</param> + /// <param name="source">The name of the source.</param> + public PerformanceCounter(PerformanceCounterCollection parentCollection, string source) + { + this.ParentCollection = parentCollection; + this.Source = source; + this.Entries = new Stack<PerformanceCounterEntry>(this.MaxEntries); + } + + /// <summary>Add a performance counter entry to the list, update monitoring, and raise alerts if needed.</summary> + /// <param name="entry">The entry to add.</param> + public void Add(PerformanceCounterEntry entry) + { + // add entry + if (this.Entries.Count > this.MaxEntries) + this.Entries.Pop(); + this.Entries.Add(entry); + + // update metrics + if (this.PeakPerformanceCounterEntry == null || entry.ElapsedMilliseconds > this.PeakPerformanceCounterEntry.Value.ElapsedMilliseconds) + this.PeakPerformanceCounterEntry = entry; + + // raise alert + if (this.EnableAlerts && entry.ElapsedMilliseconds > this.AlertThresholdMilliseconds) + this.ParentCollection.AddAlert(entry.ElapsedMilliseconds, this.AlertThresholdMilliseconds, new AlertContext(this.Source, entry.ElapsedMilliseconds)); + } + + /// <summary>Clear all performance counter entries and monitoring.</summary> + public void Reset() + { + this.Entries.Clear(); + this.PeakPerformanceCounterEntry = null; + } + + /// <summary>Get the peak entry.</summary> + public PerformanceCounterEntry? GetPeak() + { + return this.PeakPerformanceCounterEntry; + } + + /// <summary>Get the entry with the highest execution time.</summary> + /// <param name="range">The time range to search.</param> + /// <param name="endTime">The end time for the <paramref name="range"/>, or null for the current time.</param> + public PerformanceCounterEntry? GetPeak(TimeSpan range, DateTime? endTime = null) + { + endTime ??= DateTime.UtcNow; + DateTime startTime = endTime.Value.Subtract(range); + + return this.Entries + .Where(entry => entry.EventTime >= startTime && entry.EventTime <= endTime) + .OrderByDescending(x => x.ElapsedMilliseconds) + .FirstOrDefault(); + } + + /// <summary>Get the last entry added to the list.</summary> + public PerformanceCounterEntry? GetLastEntry() + { + if (this.Entries.Count == 0) + return null; + + return this.Entries.Peek(); + } + + /// <summary>Get the average over a given time span.</summary> + /// <param name="range">The time range to search.</param> + /// <param name="endTime">The end time for the <paramref name="range"/>, or null for the current time.</param> + public double GetAverage(TimeSpan range, DateTime? endTime = null) + { + endTime ??= DateTime.UtcNow; + DateTime startTime = endTime.Value.Subtract(range); + + double[] entries = this.Entries + .Where(entry => entry.EventTime >= startTime && entry.EventTime <= endTime) + .Select(p => p.ElapsedMilliseconds) + .ToArray(); + + return entries.Length > 0 + ? entries.Average() + : 0; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterCollection.cs b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterCollection.cs new file mode 100644 index 00000000..0bb78c74 --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterCollection.cs @@ -0,0 +1,205 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; + +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + internal class PerformanceCounterCollection + { + /********* + ** Fields + *********/ + /// <summary>The number of peak invocations to keep.</summary> + private readonly int MaxEntries = 16384; + + /// <summary>The sources involved in exceeding alert thresholds.</summary> + private readonly List<AlertContext> TriggeredPerformanceCounters = new List<AlertContext>(); + + /// <summary>The stopwatch used to track the invocation time.</summary> + private readonly Stopwatch InvocationStopwatch = new Stopwatch(); + + /// <summary>The performance counter manager.</summary> + private readonly PerformanceMonitor PerformanceMonitor; + + /// <summary>The time to calculate average calls per second.</summary> + private DateTime CallsPerSecondStart = DateTime.UtcNow; + + /// <summary>The number of invocations.</summary> + private long CallCount; + + /// <summary>The peak invocations.</summary> + private readonly Stack<PeakEntry> PeakInvocations; + + + /********* + ** Accessors + *********/ + /// <summary>The associated performance counters.</summary> + public IDictionary<string, PerformanceCounter> PerformanceCounters { get; } = new Dictionary<string, PerformanceCounter>(); + + /// <summary>The name of this collection.</summary> + public string Name { get; } + + /// <summary>Whether the source is typically invoked at least once per second.</summary> + public bool IsPerformanceCritical { get; } + + /// <summary>The alert threshold in milliseconds.</summary> + public double AlertThresholdMilliseconds { get; set; } + + /// <summary>Whether alerts are enabled.</summary> + public bool EnableAlerts { get; set; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="performanceMonitor">The performance counter manager.</param> + /// <param name="name">The name of this collection.</param> + /// <param name="isPerformanceCritical">Whether the source is typically invoked at least once per second.</param> + public PerformanceCounterCollection(PerformanceMonitor performanceMonitor, string name, bool isPerformanceCritical = false) + { + this.PeakInvocations = new Stack<PeakEntry>(this.MaxEntries); + this.Name = name; + this.PerformanceMonitor = performanceMonitor; + this.IsPerformanceCritical = isPerformanceCritical; + } + + /// <summary>Track a single invocation for a named source.</summary> + /// <param name="source">The name of the source.</param> + /// <param name="entry">The entry.</param> + public void Track(string source, PerformanceCounterEntry entry) + { + // add entry + if (!this.PerformanceCounters.ContainsKey(source)) + this.PerformanceCounters.Add(source, new PerformanceCounter(this, source)); + this.PerformanceCounters[source].Add(entry); + + // raise alert + if (this.EnableAlerts) + this.TriggeredPerformanceCounters.Add(new AlertContext(source, entry.ElapsedMilliseconds)); + } + + /// <summary>Get the average execution time for all non-game internal sources in milliseconds.</summary> + /// <param name="interval">The interval for which to get the average, relative to now</param> + public double GetModsAverageExecutionTime(TimeSpan interval) + { + return this.PerformanceCounters + .Where(entry => entry.Key != Constants.GamePerformanceCounterName) + .Sum(entry => entry.Value.GetAverage(interval)); + } + + /// <summary>Get the overall average execution time in milliseconds.</summary> + /// <param name="interval">The interval for which to get the average, relative to now</param> + public double GetAverageExecutionTime(TimeSpan interval) + { + return this.PerformanceCounters + .Sum(entry => entry.Value.GetAverage(interval)); + } + + /// <summary>Get the average execution time for game-internal sources in milliseconds.</summary> + public double GetGameAverageExecutionTime(TimeSpan interval) + { + return this.PerformanceCounters.TryGetValue(Constants.GamePerformanceCounterName, out PerformanceCounter gameExecTime) + ? gameExecTime.GetAverage(interval) + : 0; + } + + /// <summary>Get the peak execution time in milliseconds.</summary> + /// <param name="range">The time range to search.</param> + /// <param name="endTime">The end time for the <paramref name="range"/>, or null for the current time.</param> + public double GetPeakExecutionTime(TimeSpan range, DateTime? endTime = null) + { + if (this.PeakInvocations.Count == 0) + return 0; + + endTime ??= DateTime.UtcNow; + DateTime startTime = endTime.Value.Subtract(range); + + return this.PeakInvocations + .Where(entry => entry.EventTime >= startTime && entry.EventTime <= endTime) + .OrderByDescending(x => x.ExecutionTimeMilliseconds) + .Select(p => p.ExecutionTimeMilliseconds) + .FirstOrDefault(); + } + + /// <summary>Start tracking the invocation of this collection.</summary> + public void BeginTrackInvocation() + { + this.TriggeredPerformanceCounters.Clear(); + this.InvocationStopwatch.Reset(); + this.InvocationStopwatch.Start(); + + this.CallCount++; + } + + /// <summary>End tracking the invocation of this collection, and raise an alert if needed.</summary> + public void EndTrackInvocation() + { + this.InvocationStopwatch.Stop(); + + // add invocation + if (this.PeakInvocations.Count >= this.MaxEntries) + this.PeakInvocations.Pop(); + this.PeakInvocations.Push(new PeakEntry(this.InvocationStopwatch.Elapsed.TotalMilliseconds, DateTime.UtcNow, this.TriggeredPerformanceCounters.ToArray())); + + // raise alert + if (this.EnableAlerts && this.InvocationStopwatch.Elapsed.TotalMilliseconds >= this.AlertThresholdMilliseconds) + this.AddAlert(this.InvocationStopwatch.Elapsed.TotalMilliseconds, this.AlertThresholdMilliseconds, this.TriggeredPerformanceCounters.ToArray()); + } + + /// <summary>Add an alert.</summary> + /// <param name="executionTimeMilliseconds">The execution time in milliseconds.</param> + /// <param name="thresholdMilliseconds">The configured threshold.</param> + /// <param name="alerts">The sources involved in exceeding the threshold.</param> + public void AddAlert(double executionTimeMilliseconds, double thresholdMilliseconds, AlertContext[] alerts) + { + this.PerformanceMonitor.AddAlert( + new AlertEntry(this, executionTimeMilliseconds, thresholdMilliseconds, alerts) + ); + } + + /// <summary>Add an alert.</summary> + /// <param name="executionTimeMilliseconds">The execution time in milliseconds.</param> + /// <param name="thresholdMilliseconds">The configured threshold.</param> + /// <param name="alert">The source involved in exceeding the threshold.</param> + public void AddAlert(double executionTimeMilliseconds, double thresholdMilliseconds, AlertContext alert) + { + this.AddAlert(executionTimeMilliseconds, thresholdMilliseconds, new[] { alert }); + } + + /// <summary>Reset the calls per second counter.</summary> + public void ResetCallsPerSecond() + { + this.CallCount = 0; + this.CallsPerSecondStart = DateTime.UtcNow; + } + + /// <summary>Reset all performance counters in this collection.</summary> + public void Reset() + { + this.PeakInvocations.Clear(); + foreach (var counter in this.PerformanceCounters) + counter.Value.Reset(); + } + + /// <summary>Reset the performance counter for a specific source.</summary> + /// <param name="source">The source name.</param> + public void ResetSource(string source) + { + foreach (var i in this.PerformanceCounters) + if (i.Value.Source.Equals(source, StringComparison.InvariantCultureIgnoreCase)) + i.Value.Reset(); + } + + /// <summary>Get the average calls per second.</summary> + public long GetAverageCallsPerSecond() + { + long runtimeInSeconds = (long)DateTime.UtcNow.Subtract(this.CallsPerSecondStart).TotalSeconds; + return runtimeInSeconds > 0 + ? this.CallCount / runtimeInSeconds + : 0; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterEntry.cs b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterEntry.cs new file mode 100644 index 00000000..8adbd88d --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceCounterEntry.cs @@ -0,0 +1,30 @@ +using System; + +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>A single performance counter entry.</summary> + internal struct PerformanceCounterEntry + { + /********* + ** Accessors + *********/ + /// <summary>When the entry occurred.</summary> + public DateTime EventTime { get; } + + /// <summary>The elapsed milliseconds.</summary> + public double ElapsedMilliseconds { get; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="eventTime">When the entry occurred.</param> + /// <param name="elapsedMilliseconds">The elapsed milliseconds.</param> + public PerformanceCounterEntry(DateTime eventTime, double elapsedMilliseconds) + { + this.EventTime = eventTime; + this.ElapsedMilliseconds = elapsedMilliseconds; + } + } +} diff --git a/src/SMAPI/Framework/PerformanceMonitoring/PerformanceMonitor.cs b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceMonitor.cs new file mode 100644 index 00000000..dfc4f31a --- /dev/null +++ b/src/SMAPI/Framework/PerformanceMonitoring/PerformanceMonitor.cs @@ -0,0 +1,184 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Text; +using StardewModdingAPI.Framework.Events; + +namespace StardewModdingAPI.Framework.PerformanceMonitoring +{ + /// <summary>Tracks performance metrics.</summary> + internal class PerformanceMonitor + { + /********* + ** Fields + *********/ + /// <summary>The recorded alerts.</summary> + private readonly IList<AlertEntry> Alerts = new List<AlertEntry>(); + + /// <summary>The monitor for output logging.</summary> + private readonly IMonitor Monitor; + + /// <summary>The invocation stopwatch.</summary> + private readonly Stopwatch InvocationStopwatch = new Stopwatch(); + + /// <summary>The underlying performance counter collections.</summary> + private readonly IDictionary<string, PerformanceCounterCollection> Collections = new Dictionary<string, PerformanceCounterCollection>(StringComparer.InvariantCultureIgnoreCase); + + + /********* + ** Accessors + *********/ + /// <summary>Whether alerts are paused.</summary> + public bool PauseAlerts { get; set; } + + /// <summary>Whether performance counter tracking is enabled.</summary> + public bool EnableTracking { get; set; } + + + /********* + ** Public methods + *********/ + /// <summary>Construct an instance.</summary> + /// <param name="monitor">The monitor for output logging.</param> + public PerformanceMonitor(IMonitor monitor) + { + this.Monitor = monitor; + } + + /// <summary>Reset all performance counters in all collections.</summary> + public void Reset() + { + foreach (PerformanceCounterCollection collection in this.Collections.Values) + collection.Reset(); + } + + /// <summary>Track the invocation time for a collection.</summary> + /// <param name="collectionName">The name of the collection.</param> + /// <param name="action">The action to execute and track.</param> + public void Track(string collectionName, Action action) + { + if (!this.EnableTracking) + { + action(); + return; + } + + PerformanceCounterCollection collection = this.GetOrCreateCollectionByName(collectionName); + collection.BeginTrackInvocation(); + try + { + action(); + } + finally + { + collection.EndTrackInvocation(); + } + } + + /// <summary>Track a single performance counter invocation in a specific collection.</summary> + /// <param name="collectionName">The name of the collection.</param> + /// <param name="sourceName">The name of the source.</param> + /// <param name="action">The action to execute and track.</param> + public void Track(string collectionName, string sourceName, Action action) + { + if (!this.EnableTracking) + { + action(); + return; + } + + PerformanceCounterCollection collection = this.GetOrCreateCollectionByName(collectionName); + DateTime eventTime = DateTime.UtcNow; + this.InvocationStopwatch.Reset(); + this.InvocationStopwatch.Start(); + + try + { + action(); + } + finally + { + this.InvocationStopwatch.Stop(); + collection.Track(sourceName, new PerformanceCounterEntry(eventTime, this.InvocationStopwatch.Elapsed.TotalMilliseconds)); + } + } + + /// <summary>Reset the performance counters for a specific collection.</summary> + /// <param name="name">The collection name.</param> + public void ResetCollection(string name) + { + if (this.Collections.TryGetValue(name, out PerformanceCounterCollection collection)) + { + collection.ResetCallsPerSecond(); + collection.Reset(); + } + } + + /// <summary>Reset performance counters for a specific source.</summary> + /// <param name="name">The name of the source.</param> + public void ResetSource(string name) + { + foreach (PerformanceCounterCollection performanceCounterCollection in this.Collections.Values) + performanceCounterCollection.ResetSource(name); + } + + /// <summary>Print any queued alerts.</summary> + public void PrintQueuedAlerts() + { + if (this.Alerts.Count == 0) + return; + + StringBuilder report = new StringBuilder(); + + foreach (AlertEntry alert in this.Alerts) + { + report.AppendLine($"{alert.Collection.Name} took {alert.ExecutionTimeMilliseconds:F2}ms (exceeded threshold of {alert.ThresholdMilliseconds:F2}ms)"); + + foreach (AlertContext context in alert.Context.OrderByDescending(p => p.Elapsed)) + report.AppendLine(context.ToString()); + } + + this.Alerts.Clear(); + this.Monitor.Log(report.ToString(), LogLevel.Error); + } + + /// <summary>Add an alert to the queue.</summary> + /// <param name="entry">The alert to add.</param> + public void AddAlert(AlertEntry entry) + { + if (!this.PauseAlerts) + this.Alerts.Add(entry); + } + + /// <summary>Initialize the default performance counter collections.</summary> + /// <param name="eventManager">The event manager.</param> + public void InitializePerformanceCounterCollections(EventManager eventManager) + { + foreach (IManagedEvent @event in eventManager.GetAllEvents()) + this.Collections[@event.EventName] = new PerformanceCounterCollection(this, @event.EventName, @event.IsPerformanceCritical); + } + + /// <summary>Get the underlying performance counters.</summary> + public IEnumerable<PerformanceCounterCollection> GetCollections() + { + return this.Collections.Values; + } + + + /********* + ** Public methods + *********/ + /// <summary>Get a collection by name and creates it if it doesn't exist.</summary> + /// <param name="name">The name of the collection.</param> + private PerformanceCounterCollection GetOrCreateCollectionByName(string name) + { + if (!this.Collections.TryGetValue(name, out PerformanceCounterCollection collection)) + { + collection = new PerformanceCounterCollection(this, name); + this.Collections[name] = collection; + } + return collection; + } + } +} diff --git a/src/SMAPI/Framework/SCore.cs b/src/SMAPI/Framework/SCore.cs index 81b7c2e8..9139b371 100644 --- a/src/SMAPI/Framework/SCore.cs +++ b/src/SMAPI/Framework/SCore.cs @@ -23,6 +23,7 @@ using StardewModdingAPI.Framework.Models; using StardewModdingAPI.Framework.ModHelpers; using StardewModdingAPI.Framework.ModLoading; using StardewModdingAPI.Framework.Patching; +using StardewModdingAPI.Framework.PerformanceMonitoring; using StardewModdingAPI.Framework.Reflection; using StardewModdingAPI.Framework.Serialization; using StardewModdingAPI.Patches; @@ -109,7 +110,7 @@ namespace StardewModdingAPI.Framework "Oops! Steam achievements won't work because Steam isn't loaded. You can launch the game through Steam to fix that.", #endif logLevel: LogLevel.Error - ), + ), // save file not found error new ReplaceLogPattern( @@ -133,6 +134,10 @@ namespace StardewModdingAPI.Framework /// <remarks>This is initialized after the game starts. This is accessed directly because it's not part of the normal class model.</remarks> internal static DeprecationManager DeprecationManager { get; private set; } + /// <summary>Manages performance counters.</summary> + /// <remarks>This is initialized after the game starts. This is non-private for use by Console Commands.</remarks> + internal static PerformanceMonitor PerformanceMonitor { get; private set; } + /********* ** Public methods @@ -164,7 +169,11 @@ namespace StardewModdingAPI.Framework ShowFullStampInConsole = this.Settings.DeveloperMode }; this.MonitorForGame = this.GetSecondaryMonitor("game"); - this.EventManager = new EventManager(this.Monitor, this.ModRegistry); + + SCore.PerformanceMonitor = new PerformanceMonitor(this.Monitor); + this.EventManager = new EventManager(this.Monitor, this.ModRegistry, SCore.PerformanceMonitor); + SCore.PerformanceMonitor.InitializePerformanceCounterCollections(this.EventManager); + SCore.DeprecationManager = new DeprecationManager(this.Monitor, this.ModRegistry); // redirect direct console output @@ -242,6 +251,7 @@ namespace StardewModdingAPI.Framework jsonHelper: this.Toolkit.JsonHelper, modRegistry: this.ModRegistry, deprecationManager: SCore.DeprecationManager, + performanceMonitor: SCore.PerformanceMonitor, onGameInitialized: this.InitializeAfterGameStart, onGameExiting: this.Dispose, cancellationToken: this.CancellationToken, diff --git a/src/SMAPI/Framework/SGame.cs b/src/SMAPI/Framework/SGame.cs index d6c3b836..4b346059 100644 --- a/src/SMAPI/Framework/SGame.cs +++ b/src/SMAPI/Framework/SGame.cs @@ -17,6 +17,7 @@ using StardewModdingAPI.Framework.Content; using StardewModdingAPI.Framework.Events; using StardewModdingAPI.Framework.Input; using StardewModdingAPI.Framework.Networking; +using StardewModdingAPI.Framework.PerformanceMonitoring; using StardewModdingAPI.Framework.Reflection; using StardewModdingAPI.Framework.StateTracking.Comparers; using StardewModdingAPI.Framework.StateTracking.Snapshots; @@ -58,6 +59,9 @@ namespace StardewModdingAPI.Framework /// <summary>Manages deprecation warnings.</summary> private readonly DeprecationManager DeprecationManager; + /// <summary>Tracks performance metrics.</summary> + private readonly PerformanceMonitor PerformanceMonitor; + /// <summary>The maximum number of consecutive attempts SMAPI should make to recover from a draw error.</summary> private readonly Countdown DrawCrashTimer = new Countdown(60); // 60 ticks = roughly one second @@ -152,11 +156,12 @@ namespace StardewModdingAPI.Framework /// <param name="jsonHelper">Encapsulates SMAPI's JSON file parsing.</param> /// <param name="modRegistry">Tracks the installed mods.</param> /// <param name="deprecationManager">Manages deprecation warnings.</param> + /// <param name="performanceMonitor">Tracks performance metrics.</param> /// <param name="onGameInitialized">A callback to invoke after the game finishes initializing.</param> /// <param name="onGameExiting">A callback to invoke when the game exits.</param> /// <param name="cancellationToken">Propagates notification that SMAPI should exit.</param> /// <param name="logNetworkTraffic">Whether to log network traffic.</param> - internal SGame(Monitor monitor, IMonitor monitorForGame, Reflector reflection, Translator translator, EventManager eventManager, JsonHelper jsonHelper, ModRegistry modRegistry, DeprecationManager deprecationManager, Action onGameInitialized, Action onGameExiting, CancellationTokenSource cancellationToken, bool logNetworkTraffic) + internal SGame(Monitor monitor, IMonitor monitorForGame, Reflector reflection, Translator translator, EventManager eventManager, JsonHelper jsonHelper, ModRegistry modRegistry, DeprecationManager deprecationManager, PerformanceMonitor performanceMonitor, Action onGameInitialized, Action onGameExiting, CancellationTokenSource cancellationToken, bool logNetworkTraffic) { this.OnLoadingFirstAsset = SGame.ConstructorHack.OnLoadingFirstAsset; SGame.ConstructorHack = null; @@ -176,6 +181,7 @@ namespace StardewModdingAPI.Framework this.Reflection = reflection; this.Translator = translator; this.DeprecationManager = deprecationManager; + this.PerformanceMonitor = performanceMonitor; this.OnGameInitialized = onGameInitialized; this.OnGameExiting = onGameExiting; Game1.input = new SInputState(); @@ -307,6 +313,7 @@ namespace StardewModdingAPI.Framework try { this.DeprecationManager.PrintQueued(); + this.PerformanceMonitor.PrintQueuedAlerts(); /********* ** First-tick initialization @@ -382,7 +389,7 @@ namespace StardewModdingAPI.Framework // state while mods are running their code. This is risky, because data changes can // conflict (e.g. collection changed during enumeration errors) and data may change // unexpectedly from one mod instruction to the next. - // + // // Therefore we can just run Game1.Update here without raising any SMAPI events. There's // a small chance that the task will finish after we defer but before the game checks, // which means technically events should be raised, but the effects of missing one |