diff --git a/OpenRA.Game/Support/PerfTimer.cs b/OpenRA.Game/Support/PerfTimer.cs index 772adf92c5..29043b6bb5 100755 --- a/OpenRA.Game/Support/PerfTimer.cs +++ b/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 children; - // - // Hacks to give the output a tree-like structure - // - static ThreadLocal depth = new ThreadLocal(); - static ThreadLocal prevHeader = new ThreadLocal(); + static ThreadLocal Parent = new ThreadLocal(); + + // 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(); + parent.children.Add(this); } - else - { - s = GetOneLiner(Indentation, this.Name); - prevHeader.Value = null; - } - - Log.Write("perf", FormatString, s, Math.Round(this.sw.Elapsed.TotalMilliseconds)); } + void Write() + { + 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 } } diff --git a/OpenRA.Game/Traits/Util.cs b/OpenRA.Game/Traits/Util.cs index 851ed4caa1..b09d77ad1f 100644 --- a/OpenRA.Game/Traits/Util.cs +++ b/OpenRA.Game/Traits/Util.cs @@ -82,11 +82,8 @@ namespace OpenRA.Traits { var prev = act; - var sw = Stopwatch.StartNew(); - 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); + using (new PerfTimer("[{0}] Activity: {1}".F(Game.LocalTick, prev), (int)Game.Settings.Debug.LongTickThreshold.TotalMilliseconds)) + act = act.Tick(self); if (prev == act) break; diff --git a/OpenRA.Game/World.cs b/OpenRA.Game/World.cs index bab4df4aff..cd0f8f4d90 100644 --- a/OpenRA.Game/World.cs +++ b/OpenRA.Game/World.cs @@ -229,13 +229,9 @@ namespace OpenRA foreach (var a in actors) a.Tick(); - ActorsWithTrait().DoTimed(x => x.Trait.Tick(x.Actor), - "[{2}] Trait: {0} ({1:0.000} ms)", - Game.Settings.Debug.LongTickThreshold); + ActorsWithTrait().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) diff --git a/OpenRA.Game/WorldUtils.cs b/OpenRA.Game/WorldUtils.cs index 28eefaed34..90cce2b55e 100644 --- a/OpenRA.Game/WorldUtils.cs +++ b/OpenRA.Game/WorldUtils.cs @@ -174,15 +174,10 @@ namespace OpenRA public static void DoTimed(this IEnumerable e, Action a, string text, TimeSpan time) { - var sw = Stopwatch.StartNew(); - e.Do(x => { - var t = sw.Elapsed; - a(x); - var dt = sw.Elapsed - t; - if (dt > time) - Log.Write("perf", text, x, dt.TotalMilliseconds, Game.LocalTick); + using (new PerfTimer("[{0}] {1}: {2}".F(Game.LocalTick, text, x), (int)time.TotalMilliseconds)) + a(x); }); }