Give PerfTimer the ability to write only slow operations to the log

This is useful to ignore fast operations that just spam the log.

The class had to be reworked because it couldn't properly handle cases
where all of a node's children where below the threshold.

Also changed DoTimed() and RunActivity() to use PerfTimer.

OpenRA.Game/Support/PerfTimer.cs

@@ -9,6 +9,7 @@
 #endregion
 
 using System;
+using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
 using System.Threading;
@@ -17,52 +18,65 @@ namespace OpenRA.Support
 {
 	public class PerfTimer : IDisposable
 	{
-		readonly Stopwatch sw = Stopwatch.StartNew();
-		readonly string Name;
+		readonly Stopwatch sw;
+		readonly string name;
+		readonly int thresholdMs;
+		readonly int depth;
+		readonly PerfTimer parent;
+		List<PerfTimer> children;
 
-		//
-		// Hacks to give the output a tree-like structure
-		//
-		static ThreadLocal<int> depth = new ThreadLocal<int>();
-		static ThreadLocal<string> prevHeader = new ThreadLocal<string>();
+		static ThreadLocal<PerfTimer> Parent = new ThreadLocal<PerfTimer>();
+
+		// Tree settings
 		const int MaxWidth = 60, Digits = 6;
 		const int MaxIndentedLabel = MaxWidth - Digits;
 		const string IndentationString = "|   ";
-		readonly string FormatString = "{0," + MaxIndentedLabel + "} {1," + Digits + "} ms";
+		static readonly string FormatString = "{0," + MaxIndentedLabel + "} {1," + Digits + "} ms";
 
-		public PerfTimer(string name)
+		public PerfTimer(string name, int thresholdMs = 0)
 		{
-			if (prevHeader.Value != null)
-			{
-				Log.Write("perf", prevHeader.Value);
-				prevHeader.Value = null;
-			}
+			this.name = name;
+			this.thresholdMs = thresholdMs;
 
-			this.Name = name;
+			parent = Parent.Value;
+			depth = parent == null ? 0 : parent.depth + 1;
+			Parent.Value = this;
 
-			prevHeader.Value = GetHeader(Indentation, this.Name);
-			depth.Value++;
+			sw = Stopwatch.StartNew();
 		}
 
 		public void Dispose()
 		{
-			depth.Value--;
+			sw.Stop();
 
-			string s;
+			Parent.Value = parent;
 
-			if (prevHeader.Value == null)
+			if (parent == null)
+				Write();
+			else if (sw.Elapsed.TotalMilliseconds > thresholdMs)
 			{
-				s = GetFooter(Indentation);
+				if (parent.children == null)
+					parent.children = new List<PerfTimer>();
+				parent.children.Add(this);
 			}
-			else
+		}
+
+		void Write()
 		{
-				s = GetOneLiner(Indentation, this.Name);
-				prevHeader.Value = null;
-			}
-
-			Log.Write("perf", FormatString, s, Math.Round(this.sw.Elapsed.TotalMilliseconds));
+			var elapsedMs = Math.Round(this.sw.Elapsed.TotalMilliseconds);
+
+			if (children != null)
+			{
+				Log.Write("perf", GetHeader(Indentation, this.name));
+				foreach (var child in children)
+					child.Write();
+				Log.Write("perf", FormatString, GetFooter(Indentation), elapsedMs);
+			}
+			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));
@@ -101,18 +115,20 @@ namespace OpenRA.Support
 			return s.Substring(0, length);
 		}
 
-		static string Indentation
+		string Indentation
 		{
 			get
 			{
-				var d = depth.Value;
-				if (d == 1)
-					return IndentationString;
-				else if (d <= 0)
+				if (depth <= 0)
 					return string.Empty;
+				else if (depth == 1)
+					return IndentationString;
+				else if (depth == 2)
+					return string.Concat(IndentationString, IndentationString);
 				else
-					return string.Concat(Enumerable.Repeat(IndentationString, depth.Value));
+					return string.Concat(Enumerable.Repeat(IndentationString, depth));
 			}
 		}
+		#endregion
 	}
 }

OpenRA.Game/Traits/Util.cs

@@ -82,11 +82,8 @@ namespace OpenRA.Traits
 			{
 				var prev = act;
 
-				var sw = Stopwatch.StartNew();
+				using (new PerfTimer("[{0}] Activity: {1}".F(Game.LocalTick, prev), (int)Game.Settings.Debug.LongTickThreshold.TotalMilliseconds))
 					act = act.Tick(self);
-				var dt = sw.Elapsed;
-				if (dt > Game.Settings.Debug.LongTickThreshold)
-					Log.Write("perf", "[{2}] Activity: {0} ({1:0.000} ms)", prev, dt.TotalMilliseconds, Game.LocalTick);
 
 				if (prev == act)
 					break;

OpenRA.Game/World.cs

@@ -229,13 +229,9 @@ namespace OpenRA
 					foreach (var a in actors)
 						a.Tick();
 
-				ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor),
-					"[{2}] Trait: {0} ({1:0.000} ms)",
-					Game.Settings.Debug.LongTickThreshold);
+				ActorsWithTrait<ITick>().DoTimed(x => x.Trait.Tick(x.Actor), "Trait", Game.Settings.Debug.LongTickThreshold);
 
-				effects.DoTimed(e => e.Tick(this),
-					"[{2}] Effect: {0} ({1:0.000} ms)",
-					Game.Settings.Debug.LongTickThreshold);
+				effects.DoTimed(e => e.Tick(this), "Effect", Game.Settings.Debug.LongTickThreshold);
 			}
 
 			while (frameEndActions.Count != 0)

OpenRA.Game/WorldUtils.cs

@@ -174,15 +174,10 @@ namespace OpenRA
 
 		public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text, TimeSpan time)
 		{
-			var sw = Stopwatch.StartNew();
-
 			e.Do(x =>
 			{
-				var t = sw.Elapsed;
+				using (new PerfTimer("[{0}] {1}: {2}".F(Game.LocalTick, text, x), (int)time.TotalMilliseconds))
 					a(x);
-				var dt = sw.Elapsed - t;
-				if (dt > time)
-					Log.Write("perf", text, x, dt.TotalMilliseconds, Game.LocalTick);
 			});
 		}