diff --git a/OpenRA.Game/Support/PerfTickLogger.cs b/OpenRA.Game/Support/PerfTickLogger.cs index 2b3ca39591..ae1fc21057 100644 --- a/OpenRA.Game/Support/PerfTickLogger.cs +++ b/OpenRA.Game/Support/PerfTickLogger.cs @@ -13,36 +13,43 @@ using System.Diagnostics; namespace OpenRA.Support { - public sealed class PerfTickLogger + public static class PerfTickLogger { - readonly DebugSettings settings = Game.Settings.Debug; - readonly long threshold = PerfTimer.LongTickThresholdInStopwatchTicks; - long start; - long current; - bool enabled; + public const long TimestampDisabled = 0L; - long CurrentTimestamp => enabled ? Stopwatch.GetTimestamp() : 0L; + static float durationThresholdMs = Game.Settings.Debug.LongTickThresholdMs; + static long durationThresholdTicks = PerfTimer.MillisToTicks(Game.Settings.Debug.LongTickThresholdMs); - public void Start() + /// Retrieve the current timestamp. + /// TimestampDisabled if performance logging is disabled. + public static long GetTimestamp() { - enabled = settings.EnableSimulationPerfLogging; - start = CurrentTimestamp; - } + var settings = Game.Settings.Debug; + if (!settings.EnableSimulationPerfLogging) + return TimestampDisabled; - public void LogTickAndRestartTimer(string name, object item) - { - if (!enabled) - return; - - current = CurrentTimestamp; - if (current - start > threshold) + // TODO: Let settings notify listeners on changes + if (durationThresholdMs != settings.LongTickThresholdMs) { - PerfTimer.LogLongTick(start, current, name, item); - start = CurrentTimestamp; - return; + durationThresholdMs = Game.Settings.Debug.LongTickThresholdMs; + durationThresholdTicks = PerfTimer.MillisToTicks(durationThresholdMs); } - start = current; + return Stopwatch.GetTimestamp(); + } + + /// Logs an entry in the performance log when the current time since the start tick exceeds the game debug setting `LongTickThresholdMs`. + /// TimestampDisabled if performance logging is disabled. + public static long LogLongTick(long startTimestamp, string name, object item) + { + if (startTimestamp == TimestampDisabled) + return TimestampDisabled; + + var currentTimetamp = Stopwatch.GetTimestamp(); + if (currentTimetamp - startTimestamp > durationThresholdTicks) + PerfTimer.LogLongTick(startTimestamp, currentTimetamp, name, item); + + return currentTimetamp; } } } diff --git a/OpenRA.Game/Support/PerfTimer.cs b/OpenRA.Game/Support/PerfTimer.cs index 6c9f0d6ea4..29961393a0 100644 --- a/OpenRA.Game/Support/PerfTimer.cs +++ b/OpenRA.Game/Support/PerfTimer.cs @@ -24,8 +24,9 @@ namespace OpenRA.Support const string IndentationString = "| "; const string FormatSeperation = " ms "; static readonly string FormatString = "{0," + Digits + ":0}" + FormatSeperation + "{1}"; + static readonly string FormatStringLongTick = "{0," + Digits + ":0}" + FormatSeperation + "[{1}] {2}: {3}"; readonly string name; - readonly float thresholdMs; + readonly long thresholdTicks; readonly byte depth; readonly PerfTimer parent; List children; @@ -36,7 +37,7 @@ namespace OpenRA.Support public PerfTimer(string name, float thresholdMs = 0) { this.name = name; - this.thresholdMs = thresholdMs; + thresholdTicks = MillisToTicks(thresholdMs); parent = ParentThreadLocal.Value; depth = parent == null ? (byte)0 : (byte)(parent.depth + 1); @@ -53,7 +54,7 @@ namespace OpenRA.Support if (parent == null) Write(); - else if (ElapsedMs > thresholdMs) + else if (ticks > thresholdTicks) { parent.children ??= new List(); parent.children.Add(this); @@ -69,23 +70,28 @@ namespace OpenRA.Support child.Write(); Log.Write("perf", string.Format(FormatString, ElapsedMs, GetFooter(Indentation))); } - else if (ElapsedMs >= thresholdMs) + else if (ticks >= thresholdTicks) Log.Write("perf", string.Format(FormatString, ElapsedMs, Indentation + name)); } + public static long MillisToTicks(float millis) + { + return (long)(Stopwatch.Frequency * millis / 1000f); + } + float ElapsedMs => 1000f * ticks / Stopwatch.Frequency; public static void LogLongTick(long startStopwatchTicks, long endStopwatchTicks, string name, object item) { var type = item.GetType(); var label = type == typeof(string) || type.IsGenericType ? item.ToString() : type.Name; - Log.Write("perf", string.Format(FormatString, + Log.Write("perf", string.Format(FormatStringLongTick, 1000f * (endStopwatchTicks - startStopwatchTicks) / Stopwatch.Frequency, - "[" + Game.LocalTick + "] " + name + ": " + label)); + Game.LocalTick, + name, + label)); } - public static long LongTickThresholdInStopwatchTicks => (long)(Stopwatch.Frequency * Game.Settings.Debug.LongTickThresholdMs / 1000f); - #region Formatting helpers static string GetHeader(string indentation, string label) { diff --git a/OpenRA.Game/TraitDictionary.cs b/OpenRA.Game/TraitDictionary.cs index d71ff980de..6fb524a7a1 100644 --- a/OpenRA.Game/TraitDictionary.cs +++ b/OpenRA.Game/TraitDictionary.cs @@ -145,7 +145,6 @@ namespace OpenRA { readonly List actors = new(); readonly List traits = new(); - readonly PerfTickLogger perfLogger = new(); public int Queries { get; private set; } @@ -305,14 +304,14 @@ namespace OpenRA public void ApplyToAllTimed(Action action, string text) { - perfLogger.Start(); + var start = PerfTickLogger.GetTimestamp(); for (var i = 0; i < actors.Count; i++) { var actor = actors[i]; var trait = traits[i]; action(actor, trait); - perfLogger.LogTickAndRestartTimer(text, trait); + start = PerfTickLogger.LogLongTick(start, text, trait); } } } diff --git a/OpenRA.Game/Traits/ActivityUtils.cs b/OpenRA.Game/Traits/ActivityUtils.cs index 9bdcc57cfd..38c33ef98a 100644 --- a/OpenRA.Game/Traits/ActivityUtils.cs +++ b/OpenRA.Game/Traits/ActivityUtils.cs @@ -19,21 +19,19 @@ namespace OpenRA.Traits public static Activity RunActivity(Actor self, Activity act) { // PERF: This is a hot path and must run with minimal added overhead. - // If there are no activities we can bail straight away and save ourselves the overhead of setting up the perf logging. if (act == null) return act; - var perfLogger = new PerfTickLogger(); - perfLogger.Start(); - while (act != null) + var start = PerfTickLogger.GetTimestamp(); + do { var prev = act; act = act.TickOuter(self); - perfLogger.LogTickAndRestartTimer("Activity", prev); - + start = PerfTickLogger.LogLongTick(start, "Activity", prev); if (act == prev) break; } + while (act != null); return act; } diff --git a/OpenRA.Game/WorldUtils.cs b/OpenRA.Game/WorldUtils.cs index ed38f3ca86..604fcd1259 100644 --- a/OpenRA.Game/WorldUtils.cs +++ b/OpenRA.Game/WorldUtils.cs @@ -66,14 +66,13 @@ namespace OpenRA { // PERF: This is a hot path and must run with minimal added overhead, so we enumerate manually // to allow us to call PerfTickLogger only once per iteration in the normal case. - var perfLogger = new PerfTickLogger(); using (var enumerator = e.GetEnumerator()) { - perfLogger.Start(); + var start = PerfTickLogger.GetTimestamp(); while (enumerator.MoveNext()) { a(enumerator.Current); - perfLogger.LogTickAndRestartTimer(text, enumerator.Current); + start = PerfTickLogger.LogLongTick(start, text, enumerator.Current); } } }