From aa834db1e30a4fc1dbf3eac70f0de65bf2351fef Mon Sep 17 00:00:00 2001 From: reaperrr Date: Sun, 21 Mar 2021 23:14:09 +0100 Subject: [PATCH] Make perf.log output for ticking things opt-in Both writing to perf.log frequently as well as GetTimestamp aren't free and hurt performance particularly on slower systems (which can have notably higher output to perf.log, further amplifying the problem). Therefore we make simulation perf logging opt-in. Additionally, logging of the current tick and tick type (local/net) is removed from debug.log, and some remnant debug logging for kills and pips is removed to keep performance-sensitive logging limited to perf.log. --- OpenRA.Game/Game.cs | 2 - OpenRA.Game/Settings.cs | 3 ++ OpenRA.Game/Support/PerfTickLogger.cs | 48 +++++++++++++++++++ OpenRA.Game/TraitDictionary.cs | 15 ++---- OpenRA.Game/Traits/ActivityUtils.cs | 23 ++------- OpenRA.Game/WorldUtils.cs | 20 ++------ OpenRA.Mods.Common/Traits/Health.cs | 5 -- .../Traits/Render/WithCargoPipsDecoration.cs | 7 ++- .../Traits/World/ValidateOrder.cs | 2 +- .../Logic/Settings/AdvancedSettingsLogic.cs | 2 + mods/cnc/chrome/settings-advanced.yaml | 7 +++ mods/common/chrome/settings-advanced.yaml | 7 +++ 12 files changed, 85 insertions(+), 56 deletions(-) create mode 100644 OpenRA.Game/Support/PerfTickLogger.cs diff --git a/OpenRA.Game/Game.cs b/OpenRA.Game/Game.cs index 52151924a6..6638ed412d 100644 --- a/OpenRA.Game/Game.cs +++ b/OpenRA.Game/Game.cs @@ -614,8 +614,6 @@ namespace OpenRA { ++orderManager.LocalFrameNumber; - Log.Write("debug", "--Tick: {0} ({1})", LocalTick, isNetTick ? "net" : "local"); - if (isNetTick) orderManager.Tick(); diff --git a/OpenRA.Game/Settings.cs b/OpenRA.Game/Settings.cs index 3a8a12a357..924c8bc6a2 100644 --- a/OpenRA.Game/Settings.cs +++ b/OpenRA.Game/Settings.cs @@ -132,6 +132,9 @@ namespace OpenRA [Desc("Enable the chat field during replays to allow use of console commands.")] public bool EnableDebugCommandsInReplays = false; + [Desc("Enable perf.log output for traits, activities and effects.")] + public bool EnableSimulationPerfLogging = false; + [Desc("Amount of time required for triggering perf.log output.")] public float LongTickThresholdMs = 1; diff --git a/OpenRA.Game/Support/PerfTickLogger.cs b/OpenRA.Game/Support/PerfTickLogger.cs new file mode 100644 index 0000000000..bb450a10bc --- /dev/null +++ b/OpenRA.Game/Support/PerfTickLogger.cs @@ -0,0 +1,48 @@ +#region Copyright & License Information +/* + * Copyright 2007-2020 The OpenRA Developers (see AUTHORS) + * This file is part of OpenRA, which is free software. It is made + * available to you under the terms of the GNU General Public License + * as published by the Free Software Foundation, either version 3 of + * the License, or (at your option) any later version. For more + * information, see COPYING. + */ +#endregion + +using System.Diagnostics; + +namespace OpenRA.Support +{ + public sealed class PerfTickLogger + { + readonly DebugSettings settings = Game.Settings.Debug; + readonly long threshold = PerfTimer.LongTickThresholdInStopwatchTicks; + long start; + long current; + bool enabled; + + long CurrentTimestamp => enabled ? Stopwatch.GetTimestamp() : 0L; + + public void Start() + { + enabled = settings.EnableSimulationPerfLogging; + start = CurrentTimestamp; + } + + public void LogTickAndRestartTimer(string name, object item) + { + if (!enabled) + return; + + current = CurrentTimestamp; + if (current - start > threshold) + { + PerfTimer.LogLongTick(start, current, name, item); + start = CurrentTimestamp; + return; + } + + start = current; + } + } +} diff --git a/OpenRA.Game/TraitDictionary.cs b/OpenRA.Game/TraitDictionary.cs index 881510dfca..4d371cc571 100644 --- a/OpenRA.Game/TraitDictionary.cs +++ b/OpenRA.Game/TraitDictionary.cs @@ -11,7 +11,6 @@ using System; using System.Collections.Generic; -using System.Diagnostics; using System.Linq; using OpenRA.Primitives; using OpenRA.Support; @@ -146,6 +145,7 @@ namespace OpenRA { readonly List actors = new List(); readonly List traits = new List(); + readonly PerfTickLogger perfLogger = new PerfTickLogger(); public int Queries { get; private set; } @@ -298,21 +298,14 @@ namespace OpenRA public void ApplyToAllTimed(Action action, string text) { - var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks; - var start = Stopwatch.GetTimestamp(); + perfLogger.Start(); for (var i = 0; i < actors.Count; i++) { var actor = actors[i]; var trait = traits[i]; action(actor, trait); - var current = Stopwatch.GetTimestamp(); - if (current - start > longTickThresholdInStopwatchTicks) - { - PerfTimer.LogLongTick(start, current, text, trait); - start = Stopwatch.GetTimestamp(); - } - else - start = current; + + perfLogger.LogTickAndRestartTimer(text, trait); } } } diff --git a/OpenRA.Game/Traits/ActivityUtils.cs b/OpenRA.Game/Traits/ActivityUtils.cs index 11b324df6e..afa0f55018 100644 --- a/OpenRA.Game/Traits/ActivityUtils.cs +++ b/OpenRA.Game/Traits/ActivityUtils.cs @@ -9,8 +9,6 @@ */ #endregion -using System.Diagnostics; -using OpenRA.Activities; using OpenRA.Support; using Activity = OpenRA.Activities.Activity; @@ -20,29 +18,18 @@ namespace OpenRA.Traits { public static Activity RunActivity(Actor self, Activity act) { - // PERF: If there are no activities we can bail straight away and save ourselves a call to - // Stopwatch.GetTimestamp. + // 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; - // PERF: This is a hot path and must run with minimal added overhead. - // Calling Stopwatch.GetTimestamp is a bit expensive, so we enumerate manually to allow us to call it only - // once per iteration in the normal case. - // See also: DoTimed - var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks; - var start = Stopwatch.GetTimestamp(); + var perfLogger = new PerfTickLogger(); + perfLogger.Start(); while (act != null) { var prev = act; act = act.TickOuter(self); - var current = Stopwatch.GetTimestamp(); - if (current - start > longTickThresholdInStopwatchTicks) - { - PerfTimer.LogLongTick(start, current, "Activity", prev); - start = Stopwatch.GetTimestamp(); - } - else - start = current; + perfLogger.LogTickAndRestartTimer("Activity", prev); if (act == prev) break; diff --git a/OpenRA.Game/WorldUtils.cs b/OpenRA.Game/WorldUtils.cs index 7f030dfc22..1ff79b8bdb 100644 --- a/OpenRA.Game/WorldUtils.cs +++ b/OpenRA.Game/WorldUtils.cs @@ -11,7 +11,6 @@ using System; using System.Collections.Generic; -using System.Diagnostics; using System.Linq; using OpenRA.Support; using OpenRA.Traits; @@ -65,25 +64,16 @@ namespace OpenRA public static void DoTimed(this IEnumerable e, Action a, string text) { - // PERF: This is a hot path and must run with minimal added overhead. - // Calling Stopwatch.GetTimestamp is a bit expensive, so we enumerate manually to allow us to call it only - // once per iteration in the normal case. - // See also: RunActivity - var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks; + // 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()) { - var start = Stopwatch.GetTimestamp(); + perfLogger.Start(); while (enumerator.MoveNext()) { a(enumerator.Current); - var current = Stopwatch.GetTimestamp(); - if (current - start > longTickThresholdInStopwatchTicks) - { - PerfTimer.LogLongTick(start, current, text, enumerator.Current); - start = Stopwatch.GetTimestamp(); - } - else - start = current; + perfLogger.LogTickAndRestartTimer(text, enumerator.Current); } } } diff --git a/OpenRA.Mods.Common/Traits/Health.cs b/OpenRA.Mods.Common/Traits/Health.cs index 5aa80b4040..cfc2662a2a 100644 --- a/OpenRA.Mods.Common/Traits/Health.cs +++ b/OpenRA.Mods.Common/Traits/Health.cs @@ -224,11 +224,6 @@ namespace OpenRA.Mods.Common.Traits if (RemoveOnDeath) self.Dispose(); - - if (attacker == null) - Log.Write("debug", "{0} #{1} was killed.", self.Info.Name, self.ActorID); - else - Log.Write("debug", "{0} #{1} killed by {2} #{3}", self.Info.Name, self.ActorID, attacker.Info.Name, attacker.ActorID); } } diff --git a/OpenRA.Mods.Common/Traits/Render/WithCargoPipsDecoration.cs b/OpenRA.Mods.Common/Traits/Render/WithCargoPipsDecoration.cs index bd002b5fa3..387f8bea00 100644 --- a/OpenRA.Mods.Common/Traits/Render/WithCargoPipsDecoration.cs +++ b/OpenRA.Mods.Common/Traits/Render/WithCargoPipsDecoration.cs @@ -67,11 +67,10 @@ namespace OpenRA.Mods.Common.Traits.Render var pi = c.Info.TraitInfo(); if (n < pi.Weight) { - var sequence = Info.FullSequence; - if (pi.CustomPipType != null && !Info.CustomPipSequences.TryGetValue(pi.CustomPipType, out sequence)) - Log.Write("debug", "Actor type {0} defines a custom pip type {1} that is not defined for actor type {2}".F(c.Info.Name, pi.CustomPipType, self.Info.Name)); + if (pi.CustomPipType != null && Info.CustomPipSequences.TryGetValue(pi.CustomPipType, out var sequence)) + return sequence; - return sequence; + return Info.FullSequence; } n -= pi.Weight; diff --git a/OpenRA.Mods.Common/Traits/World/ValidateOrder.cs b/OpenRA.Mods.Common/Traits/World/ValidateOrder.cs index 2c9b9a35fe..0d1195c496 100644 --- a/OpenRA.Mods.Common/Traits/World/ValidateOrder.cs +++ b/OpenRA.Mods.Common/Traits/World/ValidateOrder.cs @@ -29,7 +29,7 @@ namespace OpenRA.Mods.Common.Traits if (subjectClient == null) { - Log.Write("debug", "Order sent to {0}: resolved ClientIndex `{1}` doesn't exist", order.Subject.Owner.PlayerName, subjectClientId); + Log.Write("debug", "Tick {0}: Order sent to {1}: resolved ClientIndex `{2}` doesn't exist", world.WorldTick, order.Subject.Owner.PlayerName, subjectClientId); return false; } diff --git a/OpenRA.Mods.Common/Widgets/Logic/Settings/AdvancedSettingsLogic.cs b/OpenRA.Mods.Common/Widgets/Logic/Settings/AdvancedSettingsLogic.cs index 6a723e1d6d..9edd1bca08 100644 --- a/OpenRA.Mods.Common/Widgets/Logic/Settings/AdvancedSettingsLogic.cs +++ b/OpenRA.Mods.Common/Widgets/Logic/Settings/AdvancedSettingsLogic.cs @@ -53,6 +53,7 @@ namespace OpenRA.Mods.Common.Widgets.Logic SettingsUtils.BindCheckboxPref(panel, "REPLAY_COMMANDS_CHECKBOX", ds, "EnableDebugCommandsInReplays"); SettingsUtils.BindCheckboxPref(panel, "CHECKUNSYNCED_CHECKBOX", ds, "SyncCheckUnsyncedCode"); SettingsUtils.BindCheckboxPref(panel, "CHECKBOTSYNC_CHECKBOX", ds, "SyncCheckBotModuleCode"); + SettingsUtils.BindCheckboxPref(panel, "PERFLOGGING_CHECKBOX", ds, "EnableSimulationPerfLogging"); panel.Get("DEBUG_OPTIONS").IsVisible = () => ds.DisplayDeveloperSettings; panel.Get("DEBUG_HIDDEN_LABEL").IsVisible = () => !ds.DisplayDeveloperSettings; @@ -79,6 +80,7 @@ namespace OpenRA.Mods.Common.Widgets.Logic ds.SendSystemInformation = dds.SendSystemInformation; ds.CheckVersion = dds.CheckVersion; ds.EnableDebugCommandsInReplays = dds.EnableDebugCommandsInReplays; + ds.EnableSimulationPerfLogging = dds.EnableSimulationPerfLogging; }; } } diff --git a/mods/cnc/chrome/settings-advanced.yaml b/mods/cnc/chrome/settings-advanced.yaml index 92cc974cd8..560426df45 100644 --- a/mods/cnc/chrome/settings-advanced.yaml +++ b/mods/cnc/chrome/settings-advanced.yaml @@ -121,3 +121,10 @@ Container@ADVANCED_PANEL: Height: 20 Font: Regular Text: Enable Debug Commands in Replays + Checkbox@PERFLOGGING_CHECKBOX: + X: 310 + Y: 273 + Width: 300 + Height: 20 + Font: Regular + Text: Enable Tick Performance Logging diff --git a/mods/common/chrome/settings-advanced.yaml b/mods/common/chrome/settings-advanced.yaml index 5e5c6d9a05..43f5d87d58 100644 --- a/mods/common/chrome/settings-advanced.yaml +++ b/mods/common/chrome/settings-advanced.yaml @@ -115,3 +115,10 @@ Container@ADVANCED_PANEL: Height: 20 Font: Regular Text: Enable Debug Commands in Replays + Checkbox@PERFLOGGING_CHECKBOX: + X: 310 + Y: 273 + Width: 300 + Height: 20 + Font: Regular + Text: Enable Tick Performance Logging