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