Changed logging in DoTimed/RunActivity to create less overhead.

- Refactored PerfTimer to use less memory.
- Avoid using the PerfTimer in highly called methods DoTimed and RunActivity, instead tracking long ticks manually to reduce overhead and avoid memory allocations.
- Added some helper methods in PerfTimer to output information when a tick takes too long.
- Changed PerfTimer logging to output the time at the start of the line, and no longer truncate output per line.
- Settings.LongTickThreshold changed from TimeSpan to float and renamed to LongTickThresholdMs.

OpenRA.Game/Settings.cs

@@ -71,7 +71,7 @@ namespace OpenRA
 		public bool BotDebug = false;
 		public bool PerfText = false;
 		public bool PerfGraph = false;
-		public TimeSpan LongTickThreshold = TimeSpan.FromMilliseconds(1d);
+		public float LongTickThresholdMs = 1;
 		public bool SanityCheckUnsyncedCode = false;
 		public int Samples = 25;
 		public bool IgnoreVersionMismatch = false;

OpenRA.Game/Support/PerfTimer.cs

@@ -18,42 +18,42 @@ namespace OpenRA.Support
 {
 	public class PerfTimer : IDisposable
 	{
-		readonly Stopwatch sw;
 		readonly string name;
-		readonly int thresholdMs;
+		readonly float thresholdMs;
-		readonly int depth;
+		readonly byte depth;
 		readonly PerfTimer parent;
 		List<PerfTimer> children;
+		long ticks;
 
 		static ThreadLocal<PerfTimer> Parent = new ThreadLocal<PerfTimer>();
 
 		// Tree settings
-		const int MaxWidth = 60, Digits = 6;
+		const int Digits = 6;
-		const int MaxIndentedLabel = MaxWidth - Digits;
 		const string IndentationString = "|   ";
-		static readonly string FormatString = "{0," + MaxIndentedLabel + "} {1," + Digits + "} ms";
+		const string FormatSeperation = " ms ";
+		static readonly string FormatString = "{0," + Digits + ":0}" + FormatSeperation + "{1}";
 
-		public PerfTimer(string name, int thresholdMs = 0)
+		public PerfTimer(string name, float thresholdMs = 0)
 		{
 			this.name = name;
 			this.thresholdMs = thresholdMs;
 
 			parent = Parent.Value;
-			depth = parent == null ? 0 : parent.depth + 1;
+			depth = parent == null ? (byte)0 : (byte)(parent.depth + 1);
 			Parent.Value = this;
 
-			sw = Stopwatch.StartNew();
+			ticks = Stopwatch.GetTimestamp();
 		}
 
 		public void Dispose()
 		{
-			sw.Stop();
+			ticks = Stopwatch.GetTimestamp() - ticks;
 
 			Parent.Value = parent;
 
 			if (parent == null)
 				Write();
-			else if (sw.Elapsed.TotalMilliseconds > thresholdMs)
+			else if (ElapsedMs > thresholdMs)
 			{
 				if (parent.children == null)
 					parent.children = new List<PerfTimer>();
@@ -63,56 +63,45 @@ namespace OpenRA.Support
 
 		void Write()
 		{
-			var elapsedMs = Math.Round(this.sw.Elapsed.TotalMilliseconds);
-
 			if (children != null)
 			{
-				Log.Write("perf", GetHeader(Indentation, this.name));
+				Log.Write("perf", GetHeader(Indentation, name));
 				foreach (var child in children)
 					child.Write();
-				Log.Write("perf", FormatString, GetFooter(Indentation), elapsedMs);
+				Log.Write("perf", FormatString, ElapsedMs, GetFooter(Indentation));
+			}
+			else if (ElapsedMs >= thresholdMs)
+				Log.Write("perf", FormatString, ElapsedMs, Indentation + name);
+		}
+
+		float ElapsedMs { get { return 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", FormatString,
+				1000f * (endStopwatchTicks - startStopwatchTicks) / Stopwatch.Frequency,
+				"[{0}] {1}: {2}".F(Game.LocalTick, name, label));
+		}
+
+		public static long LongTickThresholdInStopwatchTicks
+		{
+			get
+			{
+				return (long)(Stopwatch.Frequency * Game.Settings.Debug.LongTickThresholdMs / 1000f);
 			}
-			else if (elapsedMs >= thresholdMs)
-				Log.Write("perf", FormatString, GetOneLiner(Indentation, this.name), elapsedMs);
 		}
 
 		#region Formatting helpers
 		static string GetHeader(string indentation, string label)
 		{
-			return string.Concat(indentation, LimitLength(label, MaxIndentedLabel - indentation.Length));
+			return string.Concat(new string(' ', Digits + FormatSeperation.Length), indentation, label);
-		}
-
-		static string GetOneLiner(string indentation, string label)
-		{
-			return string.Concat(indentation, SetLength(label, MaxIndentedLabel - indentation.Length));
 		}
 
 		static string GetFooter(string indentation)
 		{
-			return string.Concat(indentation, new string('-', MaxIndentedLabel - indentation.Length));
+			return string.Concat(indentation, new string('-', Math.Max(15, 50 - indentation.Length)));
-		}
-
-		static string LimitLength(string s, int length, int minLength = 8)
-		{
-			length = Math.Max(length, minLength);
-
-			if (s == null || s.Length <= length)
-				return s;
-
-			return s.Substring(0, length);
-		}
-
-		static string SetLength(string s, int length, int minLength = 8)
-		{
-			length = Math.Max(length, minLength);
-
-			if (s == null || s.Length == length)
-				return s;
-
-			if (s.Length < length)
-				return s.PadRight(length);
-
-			return s.Substring(0, length);
 		}
 
 		string Indentation

OpenRA.Game/Traits/Util.cs

@@ -78,17 +78,26 @@ namespace OpenRA.Traits
 
 		public static Activity RunActivity(Actor self, Activity act)
 		{
+			// Note - manual iteration here for performance due to high call volume.
+			var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
+			var start = Stopwatch.GetTimestamp();
 			while (act != null)
 			{
 				var prev = act;
-
+				act = act.Tick(self);
-				using (new PerfTimer("[{0}] Activity: {1}".F(Game.LocalTick, prev), (int)Game.Settings.Debug.LongTickThreshold.TotalMilliseconds))
+				var current = Stopwatch.GetTimestamp();
-					act = act.Tick(self);
+				if (current - start > longTickThresholdInStopwatchTicks)
-
+				{
+					PerfTimer.LogLongTick(start, current, "Activity", prev);
+					start = Stopwatch.GetTimestamp();
+				}
+				else
+				{
+					start = current;
+				}
 				if (prev == act)
 					break;
 			}
-
 			return act;
 		}
 

OpenRA.Game/World.cs

@@ -244,9 +244,9 @@ namespace OpenRA
 					foreach (var a in actors)
 						a.Tick();
 
-				ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor), "Trait", Game.Settings.Debug.LongTickThreshold);
+				ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor), "Trait");
 
-				effects.DoTimed(e => e.Tick(this), "Effect", Game.Settings.Debug.LongTickThreshold);
+				effects.DoTimed(e => e.Tick(this), "Effect");
 			}
 
 			while (frameEndActions.Count != 0)

OpenRA.Game/WorldUtils.cs

@@ -172,13 +172,28 @@ namespace OpenRA
 			}
 		}
 
-		public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text, TimeSpan time)
+		public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text)
 		{
-			e.Do(x =>
+			// Note - manual enumeration here for performance due to high call volume.
+			var longTickThresholdInStopwatchTicks = PerfTimer.LongTickThresholdInStopwatchTicks;
+			using (var enumerator = e.GetEnumerator())
 			{
-				using (new PerfTimer("[{0}] {1}: {2}".F(Game.LocalTick, text, x), (int)time.TotalMilliseconds))
+				var start = Stopwatch.GetTimestamp();
-					a(x);
+				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;
+					}
+				}
+			}
 		}
 
 		public static bool AreMutualAllies( Player a, Player b )