From df0d1360dd50038789ae4fc782ad01d2a0ab4909 Mon Sep 17 00:00:00 2001 From: Pavlos Touboulidis Date: Wed, 21 May 2014 17:18:53 +0300 Subject: [PATCH] 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 | 84 +++++++++++++++++++------------- OpenRA.Game/Traits/Util.cs | 7 +-- OpenRA.Game/World.cs | 8 +-- OpenRA.Game/WorldUtils.cs | 9 +--- 4 files changed, 56 insertions(+), 52 deletions(-) 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); }); }