PerfTickLogger, reduce overhead of logging long ticks.

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()
+		/// <summary>Retrieve the current timestamp.</summary>
+		/// <returns>TimestampDisabled if performance logging is disabled.</returns>
+		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();
+		}
+
+		/// <summary>Logs an entry in the performance log when the current time since the start tick exceeds the game debug setting `LongTickThresholdMs`.</summary>
+		/// <returns>TimestampDisabled if performance logging is disabled.</returns>
+		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;
 		}
 	}
 }

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<PerfTimer> 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<PerfTimer>();
 				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)
 		{

OpenRA.Game/TraitDictionary.cs

@@ -145,7 +145,6 @@ namespace OpenRA
 		{
 			readonly List<Actor> actors = new();
 			readonly List<T> traits = new();
-			readonly PerfTickLogger perfLogger = new();
 
 			public int Queries { get; private set; }
 
@@ -305,14 +304,14 @@ namespace OpenRA
 
 			public void ApplyToAllTimed(Action<Actor, T> 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);
 				}
 			}
 		}

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

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