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

@@ -614,8 +614,6 @@ namespace OpenRA
 					{
 						++orderManager.LocalFrameNumber;
 
-						Log.Write("debug", "--Tick: {0} ({1})", LocalTick, isNetTick ? "net" : "local");
-
 						if (isNetTick)
 							orderManager.Tick();
 

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;
 

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;
+		}
+	}
+}

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<Actor> actors = new List<Actor>();
 			readonly List<T> traits = new List<T>();
+			readonly PerfTickLogger perfLogger = new PerfTickLogger();
 
 			public int Queries { get; private set; }
 
@@ -298,21 +298,14 @@ namespace OpenRA
 
 			public void ApplyToAllTimed(Action<Actor, T> action, string text)
 			{
-				var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
+				perfLogger.Start();
-				var start = Stopwatch.GetTimestamp();
 				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)
+					perfLogger.LogTickAndRestartTimer(text, trait);
-					{
-						PerfTimer.LogLongTick(start, current, text, trait);
-						start = Stopwatch.GetTimestamp();
-					}
-					else
-						start = current;
 				}
 			}
 		}

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
+			// PERF: This is a hot path and must run with minimal added overhead.
-			// Stopwatch.GetTimestamp.
+			// 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.
+			var perfLogger = new PerfTickLogger();
-			// Calling Stopwatch.GetTimestamp is a bit expensive, so we enumerate manually to allow us to call it only
+			perfLogger.Start();
-			// once per iteration in the normal case.
-			// See also: DoTimed
-			var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
-			var start = Stopwatch.GetTimestamp();
 			while (act != null)
 			{
 				var prev = act;
 				act = act.TickOuter(self);
-				var current = Stopwatch.GetTimestamp();
+				perfLogger.LogTickAndRestartTimer("Activity", prev);
-				if (current - start > longTickThresholdInStopwatchTicks)
-				{
-					PerfTimer.LogLongTick(start, current, "Activity", prev);
-					start = Stopwatch.GetTimestamp();
-				}
-				else
-					start = current;
 
 				if (act == prev)
 					break;

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<T>(this IEnumerable<T> e, Action<T> a, string text)
 		{
-			// PERF: This is a hot path and must run with minimal added overhead.
+			// PERF: This is a hot path and must run with minimal added overhead, so we enumerate manually
-			// Calling Stopwatch.GetTimestamp is a bit expensive, so we enumerate manually to allow us to call it only
+			// to allow us to call PerfTickLogger only once per iteration in the normal case.
-			// once per iteration in the normal case.
+			var perfLogger = new PerfTickLogger();
-			// See also: RunActivity
-			var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
 			using (var enumerator = e.GetEnumerator())
 			{
-				var start = Stopwatch.GetTimestamp();
+				perfLogger.Start();
 				while (enumerator.MoveNext())
 				{
 					a(enumerator.Current);
-					var current = Stopwatch.GetTimestamp();
+					perfLogger.LogTickAndRestartTimer(text, enumerator.Current);
-					if (current - start > longTickThresholdInStopwatchTicks)
-					{
-						PerfTimer.LogLongTick(start, current, text, enumerator.Current);
-						start = Stopwatch.GetTimestamp();
-					}
-					else
-						start = current;
 				}
 			}
 		}

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);
 			}
 		}
 

OpenRA.Mods.Common/Traits/Render/WithCargoPipsDecoration.cs

@@ -67,11 +67,10 @@ namespace OpenRA.Mods.Common.Traits.Render
 				var pi = c.Info.TraitInfo<PassengerInfo>();
 				if (n < pi.Weight)
 				{
-					var sequence = Info.FullSequence;
+					if (pi.CustomPipType != null && Info.CustomPipSequences.TryGetValue(pi.CustomPipType, out var sequence))
-					if (pi.CustomPipType != null && !Info.CustomPipSequences.TryGetValue(pi.CustomPipType, out sequence))
+						return 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));
 
-					return sequence;
+					return Info.FullSequence;
 				}
 
 				n -= pi.Weight;

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;
 			}
 

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;
 			};
 		}
 	}

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

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