using System; using System.Collections.Generic; using System.Linq; using System.Text; using StardewModdingAPI.Framework; using StardewModdingAPI.Framework.PerformanceMonitoring; namespace StardewModdingAPI.Mods.ConsoleCommands.Framework.Commands.Other { /// A set of commands which displays or configures performance monitoring. internal class PerformanceCounterCommand : TrainerCommand { /********* ** Fields *********/ /// The name of the command. private const string CommandName = "performance"; /// The available commands. private enum SubCommand { Summary, Detail, Reset, Trigger, Enable, Disable, Help } /********* ** Public methods *********/ /// Construct an instance. public PerformanceCounterCommand() : base(CommandName, PerformanceCounterCommand.GetDescription()) { } /// Handle the command. /// Writes messages to the console and log file. /// The command name. /// The command arguments. public override void Handle(IMonitor monitor, string command, ArgumentParser args) { // parse args SubCommand subcommand = SubCommand.Summary; { if (args.TryGet(0, "command", out string subcommandStr, false) && !Enum.TryParse(subcommandStr, ignoreCase: true, out subcommand)) { this.LogUsageError(monitor, $"Unknown command {subcommandStr}"); return; } } // handle switch (subcommand) { case SubCommand.Summary: this.HandleSummarySubCommand(monitor, args); break; case SubCommand.Detail: this.HandleDetailSubCommand(monitor, args); break; case SubCommand.Reset: this.HandleResetSubCommand(monitor, args); break; case SubCommand.Trigger: this.HandleTriggerSubCommand(monitor, args); break; case SubCommand.Enable: SCore.PerformanceMonitor.EnableTracking = true; monitor.Log("Performance counter tracking is now enabled", LogLevel.Info); break; case SubCommand.Disable: SCore.PerformanceMonitor.EnableTracking = false; monitor.Log("Performance counter tracking is now disabled", LogLevel.Info); break; case SubCommand.Help: this.OutputHelp(monitor, args.TryGet(1, "command", out _) ? subcommand : null as SubCommand?); break; default: this.LogUsageError(monitor, $"Unknown command {subcommand}"); break; } } /********* ** Private methods *********/ /// Handles the summary sub command. /// Writes messages to the console and log file. /// The command arguments. private void HandleSummarySubCommand(IMonitor monitor, ArgumentParser args) { if (!this.AssertEnabled(monitor)) return; IEnumerable data = SCore.PerformanceMonitor.GetCollections(); double? threshold = null; if (args.TryGetDecimal(1, "threshold", out decimal t, required: false)) threshold = (double?)t; TimeSpan interval = TimeSpan.FromSeconds(60); StringBuilder report = new StringBuilder(); report.AppendLine($"Summary over the last {interval.TotalSeconds} seconds:"); report.AppendLine(this.GetTableString( data: data, header: new[] { "Collection", "Avg Calls/s", "Avg Exec Time (Game)", "Avg Exec Time (Mods)", "Avg Exec Time (Game+Mods)", "Peak Exec Time" }, getRow: item => new[] { item.Name, item.GetAverageCallsPerSecond().ToString(), this.FormatMilliseconds(item.GetGameAverageExecutionTime(interval), threshold), this.FormatMilliseconds(item.GetModsAverageExecutionTime(interval), threshold), this.FormatMilliseconds(item.GetAverageExecutionTime(interval), threshold), this.FormatMilliseconds(item.GetPeakExecutionTime(interval), threshold) }, true )); monitor.Log(report.ToString(), LogLevel.Info); } /// Handles the detail sub command. /// Writes messages to the console and log file. /// The command arguments. private void HandleDetailSubCommand(IMonitor monitor, ArgumentParser args) { if (!this.AssertEnabled(monitor)) return; // parse args double thresholdMilliseconds = 0; if (args.TryGetDecimal(1, "threshold", out decimal t, required: false)) thresholdMilliseconds = (double)t; // get collections var collections = SCore.PerformanceMonitor.GetCollections(); // render TimeSpan averageInterval = TimeSpan.FromSeconds(60); StringBuilder report = new StringBuilder($"Showing details for performance counters of {thresholdMilliseconds}+ milliseconds:\n\n"); bool anyShown = false; foreach (PerformanceCounterCollection collection in collections) { KeyValuePair[] data = collection.PerformanceCounters .Where(p => p.Value.GetAverage(averageInterval) >= thresholdMilliseconds) .ToArray(); if (data.Any()) { anyShown = true; report.AppendLine($"{collection.Name}:"); report.AppendLine(this.GetTableString( data: data, header: new[] { "Mod", $"Avg Exec Time (last {(int)averageInterval.TotalSeconds}s)", "Last Exec Time", "Peak Exec Time", $"Peak Exec Time (last {(int)averageInterval.TotalSeconds}s)" }, getRow: item => new[] { item.Key, this.FormatMilliseconds(item.Value.GetAverage(averageInterval), thresholdMilliseconds), this.FormatMilliseconds(item.Value.GetLastEntry()?.ElapsedMilliseconds), this.FormatMilliseconds(item.Value.GetPeak()?.ElapsedMilliseconds), this.FormatMilliseconds(item.Value.GetPeak(averageInterval)?.ElapsedMilliseconds) }, true )); } } if (!anyShown) report.AppendLine("No performance counters found."); monitor.Log(report.ToString(), LogLevel.Info); } /// Handles the trigger sub command. /// Writes messages to the console and log file. /// The command arguments. private void HandleTriggerSubCommand(IMonitor monitor, ArgumentParser args) { if (!this.AssertEnabled(monitor)) return; if (args.TryGet(1, "mode", out string mode, false)) { switch (mode) { case "list": this.OutputAlertTriggers(monitor); break; case "collection": if (args.TryGet(2, "name", out string collectionName)) { if (args.TryGetDecimal(3, "threshold", out decimal threshold)) { if (!args.TryGet(4, "source", out string source, required: false)) source = null; this.ConfigureAlertTrigger(monitor, collectionName, source, threshold); } } break; case "pause": SCore.PerformanceMonitor.PauseAlerts = true; monitor.Log("Alerts are now paused.", LogLevel.Info); break; case "resume": SCore.PerformanceMonitor.PauseAlerts = false; monitor.Log("Alerts are now resumed.", LogLevel.Info); break; case "dump": this.OutputAlertTriggers(monitor, true); break; case "clear": this.ClearAlertTriggers(monitor); break; default: this.LogUsageError(monitor, $"Unknown mode {mode}. See '{CommandName} help trigger' for usage."); break; } } else this.OutputAlertTriggers(monitor); } /// Sets up an an alert trigger. /// Writes messages to the console and log file. /// The name of the collection. /// The name of the source, or null for all sources. /// The trigger threshold, or 0 to remove. private void ConfigureAlertTrigger(IMonitor monitor, string collectionName, string sourceName, decimal threshold) { foreach (PerformanceCounterCollection collection in SCore.PerformanceMonitor.GetCollections()) { if (collection.Name.ToLowerInvariant().Equals(collectionName.ToLowerInvariant())) { if (sourceName == null) { if (threshold != 0) { collection.EnableAlerts = true; collection.AlertThresholdMilliseconds = (double)threshold; monitor.Log($"Set up alert triggering for '{collectionName}' with '{this.FormatMilliseconds((double?)threshold)}'", LogLevel.Info); } else { collection.EnableAlerts = false; monitor.Log($"Cleared alert triggering for '{collection}'."); } return; } else { foreach (var performanceCounter in collection.PerformanceCounters) { if (performanceCounter.Value.Source.ToLowerInvariant().Equals(sourceName.ToLowerInvariant())) { if (threshold != 0) { performanceCounter.Value.EnableAlerts = true; performanceCounter.Value.AlertThresholdMilliseconds = (double)threshold; monitor.Log($"Set up alert triggering for '{sourceName}' in collection '{collectionName}' with '{this.FormatMilliseconds((double?)threshold)}", LogLevel.Info); } else performanceCounter.Value.EnableAlerts = false; return; } } monitor.Log($"Could not find the source '{sourceName}' in collection '{collectionName}'", LogLevel.Warn); return; } } } monitor.Log($"Could not find the collection '{collectionName}'", LogLevel.Warn); } /// Clears alert triggering for all collections. /// Writes messages to the console and log file. private void ClearAlertTriggers(IMonitor monitor) { int clearedTriggers = 0; foreach (PerformanceCounterCollection collection in SCore.PerformanceMonitor.GetCollections()) { if (collection.EnableAlerts) { collection.EnableAlerts = false; clearedTriggers++; } foreach (var performanceCounter in collection.PerformanceCounters) { if (performanceCounter.Value.EnableAlerts) { performanceCounter.Value.EnableAlerts = false; clearedTriggers++; } } } monitor.Log($"Cleared {clearedTriggers} alert triggers.", LogLevel.Info); } /// Lists all configured alert triggers. /// Writes messages to the console and log file. /// True to dump the triggers as commands. private void OutputAlertTriggers(IMonitor monitor, bool asDump = false) { StringBuilder report = new StringBuilder(); report.AppendLine("Configured triggers:"); report.AppendLine(); var collectionTriggers = new List(); var sourceTriggers = new List(); foreach (PerformanceCounterCollection collection in SCore.PerformanceMonitor.GetCollections()) { if (collection.EnableAlerts) collectionTriggers.Add(new CollectionTrigger(collection.Name, collection.AlertThresholdMilliseconds)); sourceTriggers.AddRange( from counter in collection.PerformanceCounters where counter.Value.EnableAlerts select new SourceTrigger(collection.Name, counter.Value.Source, counter.Value.AlertThresholdMilliseconds) ); } if (collectionTriggers.Count > 0) { report.AppendLine("Collection Triggers:"); report.AppendLine(); if (asDump) { foreach (var item in collectionTriggers) report.AppendLine($"{CommandName} trigger {item.CollectionName} {item.Threshold}"); } else { report.AppendLine(this.GetTableString( data: collectionTriggers, header: new[] { "Collection", "Threshold" }, getRow: item => new[] { item.CollectionName, this.FormatMilliseconds(item.Threshold) }, true )); } report.AppendLine(); } else report.AppendLine("No collection triggers."); if (sourceTriggers.Count > 0) { report.AppendLine("Source Triggers:"); report.AppendLine(); if (asDump) { foreach (SourceTrigger item in sourceTriggers) report.AppendLine($"{CommandName} trigger {item.CollectionName} {item.Threshold} {item.SourceName}"); } else { report.AppendLine(this.GetTableString( data: sourceTriggers, header: new[] { "Collection", "Source", "Threshold" }, getRow: item => new[] { item.CollectionName, item.SourceName, this.FormatMilliseconds(item.Threshold) }, true )); } report.AppendLine(); } else report.AppendLine("No source triggers."); monitor.Log(report.ToString(), LogLevel.Info); } /// Handles the reset sub command. /// Writes messages to the console and log file. /// The command arguments. private void HandleResetSubCommand(IMonitor monitor, ArgumentParser args) { if (!this.AssertEnabled(monitor)) return; if (args.TryGet(1, "type", out string type, false, new[] { "category", "source" })) { args.TryGet(2, "name", out string name); switch (type) { case "category": SCore.PerformanceMonitor.ResetCollection(name); monitor.Log($"All performance counters for category {name} are now cleared.", LogLevel.Info); break; case "source": SCore.PerformanceMonitor.ResetSource(name); monitor.Log($"All performance counters for source {name} are now cleared.", LogLevel.Info); break; } } else { SCore.PerformanceMonitor.Reset(); monitor.Log("All performance counters are now cleared.", LogLevel.Info); } } /// Formats the given milliseconds value into a string format. Optionally /// allows a threshold to return "-" if the value is less than the threshold. /// The milliseconds to format. Returns "-" if null /// The threshold. Any value below this is returned as "-". /// The formatted milliseconds. private string FormatMilliseconds(double? milliseconds, double? thresholdMilliseconds = null) { thresholdMilliseconds ??= 1; return milliseconds != null && milliseconds >= thresholdMilliseconds ? ((double)milliseconds).ToString("F2") : "-"; } /// Shows detailed help for a specific sub command. /// The output monitor. /// The subcommand. private void OutputHelp(IMonitor monitor, SubCommand? subcommand) { StringBuilder report = new StringBuilder(); report.AppendLine(); switch (subcommand) { case SubCommand.Detail: report.AppendLine($" {CommandName} detail "); report.AppendLine(); report.AppendLine("Displays details for a specific collection."); report.AppendLine(); report.AppendLine("Arguments:"); report.AppendLine(" Optional. The threshold in milliseconds. Any average execution time below that"); report.AppendLine(" threshold is not reported."); report.AppendLine(); report.AppendLine("Examples:"); report.AppendLine($"{CommandName} detail 5 Show counters exceeding an average of 5ms"); break; case SubCommand.Summary: report.AppendLine($"Usage: {CommandName} summary "); report.AppendLine(); report.AppendLine("Displays the performance counter summary."); report.AppendLine(); report.AppendLine("Arguments:"); report.AppendLine(" Optional. Hides the actual execution time if it's below this threshold"); report.AppendLine(); report.AppendLine("Examples:"); report.AppendLine($"{CommandName} summary Show all events"); report.AppendLine($"{CommandName} summary 5 Shows events exceeding an average of 5ms"); break; case SubCommand.Trigger: report.AppendLine($"Usage: {CommandName} trigger "); report.AppendLine($"Usage: {CommandName} trigger collection "); report.AppendLine($"Usage: {CommandName} trigger collection "); report.AppendLine(); report.AppendLine("Manages alert triggers."); report.AppendLine(); report.AppendLine("Arguments:"); report.AppendLine(" Optional. Specifies if a specific source or a specific collection should be triggered."); report.AppendLine(" - list Lists current triggers"); report.AppendLine(" - collection Sets up a trigger for a collection"); report.AppendLine(" - clear Clears all trigger entries"); report.AppendLine(" - pause Pauses triggering of alerts"); report.AppendLine(" - resume Resumes triggering of alerts"); report.AppendLine(" - dump Dumps all triggers as commands for copy and paste"); report.AppendLine(" Defaults to 'list' if not specified."); report.AppendLine(); report.AppendLine(" Required if the mode 'collection' is specified."); report.AppendLine(" Specifies the name of the collection to be triggered. Must be an exact match."); report.AppendLine(); report.AppendLine(" Optional. Specifies the name of a specific source. Must be an exact match."); report.AppendLine(); report.AppendLine(" Required if the mode 'collection' is specified."); report.AppendLine(" Specifies the threshold in milliseconds (fractions allowed)."); report.AppendLine(" Specify '0' to remove the threshold."); report.AppendLine(); report.AppendLine("Examples:"); report.AppendLine(); report.AppendLine($"{CommandName} trigger collection Display.Rendering 10"); report.AppendLine(" Sets up an alert trigger which writes on the console if the execution time of all performance counters in"); report.AppendLine(" the 'Display.Rendering' collection exceed 10 milliseconds."); report.AppendLine(); report.AppendLine($"{CommandName} trigger collection Display.Rendering 5 Pathoschild.ChestsAnywhere"); report.AppendLine(" Sets up an alert trigger to write on the console if the execution time of Pathoschild.ChestsAnywhere in"); report.AppendLine(" the 'Display.Rendering' collection exceed 5 milliseconds."); report.AppendLine(); report.AppendLine($"{CommandName} trigger collection Display.Rendering 0"); report.AppendLine(" Removes the threshold previously defined from the collection. Note that source-specific thresholds are left intact."); report.AppendLine(); report.AppendLine($"{CommandName} trigger clear"); report.AppendLine(" Clears all previously setup alert triggers."); break; case SubCommand.Reset: report.AppendLine($"Usage: {CommandName} reset "); report.AppendLine(); report.AppendLine("Resets performance counters."); report.AppendLine(); report.AppendLine("Arguments:"); report.AppendLine(" Optional. Specifies if a collection or source should be reset."); report.AppendLine(" If omitted, all performance counters are reset."); report.AppendLine(); report.AppendLine(" - source Clears performance counters for a specific source"); report.AppendLine(" - collection Clears performance counters for a specific collection"); report.AppendLine(); report.AppendLine(" Required if a is given. Specifies the name of either the collection"); report.AppendLine(" or the source. The name must be an exact match."); report.AppendLine(); report.AppendLine("Examples:"); report.AppendLine($"{CommandName} reset Resets all performance counters"); report.AppendLine($"{CommandName} reset source Pathoschild.ChestsAnywhere Resets all performance for the source named Pathoschild.ChestsAnywhere"); report.AppendLine($"{CommandName} reset collection Display.Rendering Resets all performance for the collection named Display.Rendering"); break; } report.AppendLine(); monitor.Log(report.ToString(), LogLevel.Info); } /// Get the command description. private static string GetDescription() { StringBuilder report = new StringBuilder(); report.AppendLine("Displays or configures performance monitoring to diagnose issues. Performance monitoring is disabled by default."); report.AppendLine(); report.AppendLine("For example, the counter collection named 'Display.Rendered' contains one performance"); report.AppendLine("counter when the game executes the 'Display.Rendered' event, and another counter for each mod which handles it."); report.AppendLine(); report.AppendLine($"Usage: {CommandName} "); report.AppendLine(); report.AppendLine("Commands:"); report.AppendLine(); report.AppendLine(" summary Show a summary of collections."); report.AppendLine(" detail Show a summary for a given collection."); report.AppendLine(" reset Reset all performance counters."); report.AppendLine(" trigger Configure alert triggers."); report.AppendLine(" enable Enable performance counter recording."); report.AppendLine(" disable Disable performance counter recording."); report.AppendLine(" help Show verbose help for the available commands."); report.AppendLine(); report.AppendLine($"To get help for a specific command, use '{CommandName} help ', for example:"); report.AppendLine($"{CommandName} help summary"); report.AppendLine(); report.AppendLine("Defaults to summary if no command is given."); report.AppendLine(); return report.ToString(); } /// Log a warning if performance monitoring isn't enabled. /// Writes messages to the console and log file. /// Returns whether performance monitoring is enabled. private bool AssertEnabled(IMonitor monitor) { if (!SCore.PerformanceMonitor.EnableTracking) { monitor.Log($"Performance monitoring is currently disabled; enter '{CommandName} enable' to enable it.", LogLevel.Warn); return false; } return true; } /********* ** Private models *********/ /// An alert trigger for a collection. private class CollectionTrigger { /********* ** Accessors *********/ /// The collection name. public string CollectionName { get; } /// The trigger threshold. public double Threshold { get; } /********* ** Public methods *********/ /// Construct an instance. /// The collection name. /// The trigger threshold. public CollectionTrigger(string collectionName, double threshold) { this.CollectionName = collectionName; this.Threshold = threshold; } } /// An alert triggered for a source. private class SourceTrigger : CollectionTrigger { /********* ** Accessors *********/ /// The source name. public string SourceName { get; } /********* ** Public methods *********/ /// Construct an instance. /// The collection name. /// The source name. /// The trigger threshold. public SourceTrigger(string collectionName, string sourceName, double threshold) : base(collectionName, threshold) { this.SourceName = sourceName; } } } }