diff options
Diffstat (limited to 'src/SMAPI/Framework')
| -rw-r--r-- | src/SMAPI/Framework/Events/ManagedEvent.cs | 71 | ||||
| -rw-r--r-- | src/SMAPI/Framework/SCore.cs | 247 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Utilities/EventPerformanceCounterCategory.cs | 16 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Utilities/IPerformanceCounterEvent.cs | 16 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Utilities/PerformanceCounter.cs | 102 | ||||
| -rw-r--r-- | src/SMAPI/Framework/Utilities/PerformanceCounterEntry.cs | 10 |
6 files changed, 459 insertions, 3 deletions
diff --git a/src/SMAPI/Framework/Events/ManagedEvent.cs b/src/SMAPI/Framework/Events/ManagedEvent.cs index 2afe7a03..9a5cb174 100644 --- a/src/SMAPI/Framework/Events/ManagedEvent.cs +++ b/src/SMAPI/Framework/Events/ManagedEvent.cs @@ -1,12 +1,15 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Linq; +using StardewModdingAPI.Framework.Utilities; +using PerformanceCounter = StardewModdingAPI.Framework.Utilities.PerformanceCounter; 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>: IPerformanceCounterEvent { /********* ** Fields @@ -29,6 +32,38 @@ namespace StardewModdingAPI.Framework.Events /// <summary>The cached invocation list.</summary> private EventHandler<TEventArgs>[] CachedInvocationList; + public IDictionary<string, PerformanceCounter> PerformanceCounters { get; } = new Dictionary<string, PerformanceCounter>(); + + private readonly Stopwatch Stopwatch = new Stopwatch(); + + private long EventCallCount = 0; + + private readonly DateTime StartDateTime = DateTime.Now; + + public string GetEventName() + { + return this.EventName; + } + + public double GetGameAverageExecutionTime() + { + if (this.PerformanceCounters.TryGetValue(Constants.GamePerformanceCounterName, out PerformanceCounter gameExecTime)) + { + return gameExecTime.GetAverage(); + } + + return 0; + } + + public double GetModsAverageExecutionTime() + { + return this.PerformanceCounters.Where(p => p.Key != Constants.GamePerformanceCounterName).Sum(p => p.Value.GetAverage()); + } + + public double GetAverageExecutionTime() + { + return this.PerformanceCounters.Sum(p => p.Value.GetAverage()); + } /********* ** Public methods @@ -64,6 +99,8 @@ namespace StardewModdingAPI.Framework.Events { this.Event += handler; this.AddTracking(mod, handler, this.Event?.GetInvocationList().Cast<EventHandler<TEventArgs>>()); + + } /// <summary>Remove an event handler.</summary> @@ -74,6 +111,18 @@ namespace StardewModdingAPI.Framework.Events this.RemoveTracking(handler, this.Event?.GetInvocationList().Cast<EventHandler<TEventArgs>>()); } + public long GetAverageCallsPerSecond() + { + long runtimeInSeconds = (long)DateTime.Now.Subtract(this.StartDateTime).TotalSeconds; + + if (runtimeInSeconds == 0) + { + return 0; + } + + return this.EventCallCount / runtimeInSeconds; + } + /// <summary>Raise the event and notify all handlers.</summary> /// <param name="args">The event arguments to pass.</param> public void Raise(TEventArgs args) @@ -81,11 +130,31 @@ namespace StardewModdingAPI.Framework.Events if (this.Event == null) return; + this.EventCallCount++; + foreach (EventHandler<TEventArgs> handler in this.CachedInvocationList) { try { + var performanceCounterEntry = new PerformanceCounterEntry() + { + EventTime = DateTime.Now + }; + + this.Stopwatch.Reset(); + this.Stopwatch.Start(); handler.Invoke(null, args); + this.Stopwatch.Stop(); + performanceCounterEntry.Elapsed = this.Stopwatch.Elapsed; + + string modName = this.GetSourceMod(handler)?.DisplayName ?? Constants.GamePerformanceCounterName; + + if (!this.PerformanceCounters.ContainsKey(modName)) + { + this.PerformanceCounters.Add(modName, new PerformanceCounter($"{modName}.{this.EventName}")); + } + this.PerformanceCounters[modName].Add(performanceCounterEntry); + } catch (Exception ex) { diff --git a/src/SMAPI/Framework/SCore.cs b/src/SMAPI/Framework/SCore.cs index c4841ece..6946a817 100644 --- a/src/SMAPI/Framework/SCore.cs +++ b/src/SMAPI/Framework/SCore.cs @@ -25,6 +25,7 @@ using StardewModdingAPI.Framework.ModLoading; using StardewModdingAPI.Framework.Patching; using StardewModdingAPI.Framework.Reflection; using StardewModdingAPI.Framework.Serialization; +using StardewModdingAPI.Framework.Utilities; using StardewModdingAPI.Patches; using StardewModdingAPI.Toolkit; using StardewModdingAPI.Toolkit.Framework.Clients.WebApi; @@ -33,6 +34,7 @@ using StardewModdingAPI.Toolkit.Serialization; using StardewModdingAPI.Toolkit.Utilities; using StardewValley; using Object = StardewValley.Object; +using PerformanceCounter = StardewModdingAPI.Framework.Utilities.PerformanceCounter; using ThreadState = System.Threading.ThreadState; namespace StardewModdingAPI.Framework @@ -77,6 +79,8 @@ namespace StardewModdingAPI.Framework /// <remarks>This is initialized after the game starts.</remarks> private readonly ModRegistry ModRegistry = new ModRegistry(); + private HashSet<EventPerformanceCounterCategory> PerformanceCounterEvents = new HashSet<EventPerformanceCounterCategory>(); + /// <summary>Manages SMAPI events for mods.</summary> private readonly EventManager EventManager; @@ -109,7 +113,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( @@ -162,6 +166,8 @@ namespace StardewModdingAPI.Framework }; this.MonitorForGame = this.GetSecondaryMonitor("game"); this.EventManager = new EventManager(this.Monitor, this.ModRegistry); + this.InitializePerformanceCounterEvents(); + SCore.DeprecationManager = new DeprecationManager(this.Monitor, this.ModRegistry); // redirect direct console output @@ -200,6 +206,69 @@ namespace StardewModdingAPI.Framework #endif } + private void InitializePerformanceCounterEvents() + { + this.PerformanceCounterEvents = new HashSet<EventPerformanceCounterCategory>() + { + new EventPerformanceCounterCategory(this.EventManager.MenuChanged, false), + + // Rendering Events + new EventPerformanceCounterCategory(this.EventManager.Rendering, true), + new EventPerformanceCounterCategory(this.EventManager.Rendered, true), + new EventPerformanceCounterCategory(this.EventManager.RenderingWorld, true), + new EventPerformanceCounterCategory(this.EventManager.RenderedWorld, true), + new EventPerformanceCounterCategory(this.EventManager.RenderingActiveMenu, true), + new EventPerformanceCounterCategory(this.EventManager.RenderedActiveMenu, true), + new EventPerformanceCounterCategory(this.EventManager.RenderingHud, true), + new EventPerformanceCounterCategory(this.EventManager.RenderedHud, true), + + new EventPerformanceCounterCategory(this.EventManager.WindowResized, false), + new EventPerformanceCounterCategory(this.EventManager.GameLaunched, false), + new EventPerformanceCounterCategory(this.EventManager.UpdateTicking, true), + new EventPerformanceCounterCategory(this.EventManager.UpdateTicked, true), + new EventPerformanceCounterCategory(this.EventManager.OneSecondUpdateTicking, true), + new EventPerformanceCounterCategory(this.EventManager.OneSecondUpdateTicked, true), + + new EventPerformanceCounterCategory(this.EventManager.SaveCreating, false), + new EventPerformanceCounterCategory(this.EventManager.SaveCreated, false), + new EventPerformanceCounterCategory(this.EventManager.Saving, false), + new EventPerformanceCounterCategory(this.EventManager.Saved, false), + + new EventPerformanceCounterCategory(this.EventManager.DayStarted, false), + new EventPerformanceCounterCategory(this.EventManager.DayEnding, false), + + new EventPerformanceCounterCategory(this.EventManager.TimeChanged, true), + + new EventPerformanceCounterCategory(this.EventManager.ReturnedToTitle, false), + + new EventPerformanceCounterCategory(this.EventManager.ButtonPressed, true), + new EventPerformanceCounterCategory(this.EventManager.ButtonReleased, true), + new EventPerformanceCounterCategory(this.EventManager.CursorMoved, true), + new EventPerformanceCounterCategory(this.EventManager.MouseWheelScrolled, true), + + new EventPerformanceCounterCategory(this.EventManager.PeerContextReceived, true), + new EventPerformanceCounterCategory(this.EventManager.ModMessageReceived, true), + new EventPerformanceCounterCategory(this.EventManager.PeerDisconnected, true), + new EventPerformanceCounterCategory(this.EventManager.InventoryChanged, true), + new EventPerformanceCounterCategory(this.EventManager.LevelChanged, true), + new EventPerformanceCounterCategory(this.EventManager.Warped, true), + + new EventPerformanceCounterCategory(this.EventManager.LocationListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.BuildingListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.LocationListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.DebrisListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.LargeTerrainFeatureListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.NpcListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.ObjectListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.ChestInventoryChanged, true), + new EventPerformanceCounterCategory(this.EventManager.TerrainFeatureListChanged, true), + new EventPerformanceCounterCategory(this.EventManager.LoadStageChanged, false), + new EventPerformanceCounterCategory(this.EventManager.UnvalidatedUpdateTicking, true), + new EventPerformanceCounterCategory(this.EventManager.UnvalidatedUpdateTicked, true), + + }; + } + /// <summary>Launch SMAPI.</summary> [HandleProcessCorruptedStateExceptions, SecurityCritical] // let try..catch handle corrupted state exceptions public void RunInteractively() @@ -482,6 +551,19 @@ namespace StardewModdingAPI.Framework this.Monitor.Log("Type 'help' for help, or 'help <cmd>' for a command's usage", LogLevel.Info); this.GameInstance.CommandManager.Add(null, "help", "Lists command documentation.\n\nUsage: help\nLists all available commands.\n\nUsage: help <cmd>\n- cmd: The name of a command whose documentation to display.", this.HandleCommand); this.GameInstance.CommandManager.Add(null, "reload_i18n", "Reloads translation files for all mods.\n\nUsage: reload_i18n", this.HandleCommand); + this.GameInstance.CommandManager.Add(null, "performance_counters", + "Displays performance counters.\n\n"+ + "Usage: performance_counters\n" + + "Shows the most important event invocation times\n\n"+ + "Usage: performance_counters summary|sum [all|important|name]\n"+ + "- summary or sum: Forces summary mode\n"+ + "- all, important or name: Displays all event performance counters, only important ones, or a specific event by name (defaults to important)\n\n"+ + "Usage: performance_counters [name] [threshold]\n"+ + "Shows detailed performance counters for a specific event\n"+ + "- name: The (partial) name of the event\n"+ + "- threshold: The minimum avg execution time (ms) of the event\n"+ + "", this.HandleCommand); + this.GameInstance.CommandManager.Add(null, "pc", "Alias for performance_counters", this.HandleCommand); // start handling command line input Thread inputThread = new Thread(() => @@ -1297,12 +1379,173 @@ namespace StardewModdingAPI.Framework this.ReloadTranslations(this.ModRegistry.GetAll(contentPacks: false)); this.Monitor.Log("Reloaded translation files for all mods. This only affects new translations the mods fetch; if they cached some text, it may not be updated.", LogLevel.Info); break; - + case "performance_counters": + case "pc": + this.DisplayPerformanceCounters(arguments.ToList()); + break; default: throw new NotSupportedException($"Unrecognized core SMAPI command '{name}'."); } } + /// <summary>Get an ASCII table to show tabular data in the console.</summary> + /// <typeparam name="T">The data type.</typeparam> + /// <param name="data">The data to display.</param> + /// <param name="header">The table header.</param> + /// <param name="getRow">Returns a set of fields for a data value.</param> + protected string GetTableString<T>(IEnumerable<T> data, string[] header, Func<T, string[]> getRow) + { + // get table data + int[] widths = header.Select(p => p.Length).ToArray(); + string[][] rows = data + .Select(item => + { + string[] fields = getRow(item); + if (fields.Length != widths.Length) + throw new InvalidOperationException($"Expected {widths.Length} columns, but found {fields.Length}: {string.Join(", ", fields)}"); + + for (int i = 0; i < fields.Length; i++) + widths[i] = Math.Max(widths[i], fields[i].Length); + + return fields; + }) + .ToArray(); + + // render fields + List<string[]> lines = new List<string[]>(rows.Length + 2) + { + header, + header.Select((value, i) => "".PadRight(widths[i], '-')).ToArray() + }; + lines.AddRange(rows); + + return string.Join( + Environment.NewLine, + lines.Select(line => string.Join(" | ", line.Select((field, i) => field.PadLeft(widths[i], ' ')).ToArray()) + ) + ); + } + + private void DisplayPerformanceCounters(IList<string> arguments) + { + bool showSummary = true; + bool showSummaryOnlyImportant = true; + string filterByName = null; + + if (arguments.Any()) + { + switch (arguments[0]) + { + case "summary": + case "sum": + showSummary = true; + + if (arguments.Count > 1) + { + switch (arguments[1].ToLower()) + { + case "all": + showSummaryOnlyImportant = false; + break; + case "important": + showSummaryOnlyImportant = true; + break; + default: + filterByName = arguments[1]; + break; + } + } + break; + default: + showSummary = false; + filterByName = arguments[0]; + break; + + } + } + var lastMinute = TimeSpan.FromSeconds(60); + + if (showSummary) + { + this.DisplayPerformanceCounterSummary(showSummaryOnlyImportant, filterByName); + } + else + { + var data = this.PerformanceCounterEvents.Where(p => p.Event.GetEventName().ToLowerInvariant().Contains(filterByName.ToLowerInvariant())); + + foreach (var i in data) + { + this.DisplayPerformanceCounter(i, lastMinute); + } + } + + double avgTime = PerformanceCounter.Stopwatch.ElapsedMilliseconds / (double)PerformanceCounter.EventsLogged; + this.Monitor.Log($"Logged {PerformanceCounter.EventsLogged} events in {PerformanceCounter.Stopwatch.ElapsedMilliseconds}ms (avg {avgTime:F4}ms / event)"); + + } + + private void DisplayPerformanceCounterSummary(bool showOnlyImportant, string eventNameFilter = null) + { + StringBuilder sb = new StringBuilder($"Performance Counter Summary:\n\n"); + + IEnumerable<EventPerformanceCounterCategory> data; + + if (eventNameFilter != null) + { + data = this.PerformanceCounterEvents.Where(p => p.Event.GetEventName().ToLowerInvariant().Contains(eventNameFilter.ToLowerInvariant())); + } + else + { + if (showOnlyImportant) + { + data = this.PerformanceCounterEvents.Where(p => p.IsImportant); + } + else + { + data = this.PerformanceCounterEvents; + } + } + + + sb.AppendLine(this.GetTableString( + data: data, + header: new[] {"Event", "Avg Calls/s", "Avg Execution Time (Game)", "Avg Execution Time (Mods)", "Avg Execution Time (Game+Mods)"}, + getRow: item => new[] + { + item.Event.GetEventName(), + item.Event.GetAverageCallsPerSecond().ToString(), + item.Event.GetGameAverageExecutionTime().ToString("F2") + " ms", + item.Event.GetModsAverageExecutionTime().ToString("F2") + " ms", + item.Event.GetAverageExecutionTime().ToString("F2") + " ms" + } + )); + + this.Monitor.Log(sb.ToString(), LogLevel.Info); + } + + private void DisplayPerformanceCounter (EventPerformanceCounterCategory obj, TimeSpan averageInterval) + { + StringBuilder sb = new StringBuilder($"Performance Counter for {obj.Event.GetEventName()}:\n\n"); + + sb.AppendLine(this.GetTableString( + data: obj.Event.PerformanceCounters, + header: new[] {"Mod", $"Avg Execution Time over {(int)averageInterval.TotalSeconds}s", "Last Execution Time", "Peak Execution Time"}, + getRow: item => new[] + { + item.Key, + item.Value.GetAverage(averageInterval).ToString("F2") + " ms" ?? "-", + item.Value.GetLastEntry()?.Elapsed.TotalMilliseconds.ToString("F2") + " ms" ?? "-", + item.Value.GetPeak()?.Elapsed.TotalMilliseconds.ToString("F2") + " ms" ?? "-", + } + )); + + sb.AppendLine($"Average execution time (Game+Mods): {obj.Event.GetAverageExecutionTime():F2} ms"); + sb.AppendLine($"Average execution time (Game only) : {obj.Event.GetGameAverageExecutionTime():F2} ms"); + sb.AppendLine($"Average execution time (Mods only) : {obj.Event.GetModsAverageExecutionTime():F2} ms"); + + this.Monitor.Log(sb.ToString(), LogLevel.Info); + } + /// <summary>Redirect messages logged directly to the console to the given monitor.</summary> /// <param name="gameMonitor">The monitor with which to log messages as the game.</param> /// <param name="message">The message to log.</param> diff --git a/src/SMAPI/Framework/Utilities/EventPerformanceCounterCategory.cs b/src/SMAPI/Framework/Utilities/EventPerformanceCounterCategory.cs new file mode 100644 index 00000000..14f74317 --- /dev/null +++ b/src/SMAPI/Framework/Utilities/EventPerformanceCounterCategory.cs @@ -0,0 +1,16 @@ +namespace StardewModdingAPI.Framework.Utilities +{ + public class EventPerformanceCounterCategory + { + public IPerformanceCounterEvent Event { get; } + public double MonitorThreshold { get; } + public bool IsImportant { get; } + public bool Monitor { get; } + + public EventPerformanceCounterCategory(IPerformanceCounterEvent @event, bool isImportant) + { + this.Event = @event; + this.IsImportant = isImportant; + } + } +} diff --git a/src/SMAPI/Framework/Utilities/IPerformanceCounterEvent.cs b/src/SMAPI/Framework/Utilities/IPerformanceCounterEvent.cs new file mode 100644 index 00000000..55302f90 --- /dev/null +++ b/src/SMAPI/Framework/Utilities/IPerformanceCounterEvent.cs @@ -0,0 +1,16 @@ +using System; +using System.Collections.Generic; + +namespace StardewModdingAPI.Framework.Utilities +{ + public interface IPerformanceCounterEvent + { + string GetEventName(); + long GetAverageCallsPerSecond(); + IDictionary<string, PerformanceCounter> PerformanceCounters { get; } + + double GetGameAverageExecutionTime(); + double GetModsAverageExecutionTime(); + double GetAverageExecutionTime(); + } +} diff --git a/src/SMAPI/Framework/Utilities/PerformanceCounter.cs b/src/SMAPI/Framework/Utilities/PerformanceCounter.cs new file mode 100644 index 00000000..c9ffcf5b --- /dev/null +++ b/src/SMAPI/Framework/Utilities/PerformanceCounter.cs @@ -0,0 +1,102 @@ +using System; +using System.Diagnostics; +using System.Linq; +using Cyotek.Collections.Generic; + +namespace StardewModdingAPI.Framework.Utilities +{ + public class PerformanceCounter + { + private const int MaxCount = 16384; + + public string Name { get; } + public static Stopwatch Stopwatch = new Stopwatch(); + public static long EventsLogged; + + + private readonly CircularBuffer<PerformanceCounterEntry> _counter; + + private PerformanceCounterEntry? PeakPerformanceCounterEntry; + + public PerformanceCounter(string name) + { + this.Name = name; + this._counter = new CircularBuffer<PerformanceCounterEntry>(PerformanceCounter.MaxCount); + } + + public int GetAverageCallsPerSecond() + { + var x = this._counter.GroupBy( + p => + (int) p.EventTime.Subtract( + new DateTime(1970, 1, 1) + ).TotalSeconds); + + return x.Last().Count(); + } + + public void Add(PerformanceCounterEntry entry) + { + PerformanceCounter.Stopwatch.Start(); + this._counter.Put(entry); + + if (this.PeakPerformanceCounterEntry == null) + { + this.PeakPerformanceCounterEntry = entry; + } + else + { + if (entry.Elapsed.TotalMilliseconds > this.PeakPerformanceCounterEntry.Value.Elapsed.TotalMilliseconds) + { + this.PeakPerformanceCounterEntry = entry; + } + } + + PerformanceCounter.Stopwatch.Stop(); + EventsLogged++; + } + + public PerformanceCounterEntry? GetPeak() + { + return this.PeakPerformanceCounterEntry; + } + + public void ResetPeak() + { + this.PeakPerformanceCounterEntry = null; + } + + public PerformanceCounterEntry? GetLastEntry() + { + if (this._counter.IsEmpty) + { + return null; + } + return this._counter.PeekLast(); + } + + public double GetAverage() + { + if (this._counter.IsEmpty) + { + return 0; + } + + return this._counter.Average(p => p.Elapsed.TotalMilliseconds); + } + + public double GetAverage(TimeSpan range) + { + if (this._counter.IsEmpty) + { + return 0; + } + + var lastTime = this._counter.Max(x => x.EventTime); + var start = lastTime.Subtract(range); + + var entries = this._counter.Where(x => (x.EventTime >= start) && (x.EventTime <= lastTime)); + return entries.Average(x => x.Elapsed.TotalMilliseconds); + } + } +} diff --git a/src/SMAPI/Framework/Utilities/PerformanceCounterEntry.cs b/src/SMAPI/Framework/Utilities/PerformanceCounterEntry.cs new file mode 100644 index 00000000..8e156a32 --- /dev/null +++ b/src/SMAPI/Framework/Utilities/PerformanceCounterEntry.cs @@ -0,0 +1,10 @@ +using System; + +namespace StardewModdingAPI.Framework.Utilities +{ + public struct PerformanceCounterEntry + { + public DateTime EventTime; + public TimeSpan Elapsed; + } +} |