diff --git a/OpenRA.Game/Settings.cs b/OpenRA.Game/Settings.cs index a1c8cde4cc..f13e5da7cc 100644 --- a/OpenRA.Game/Settings.cs +++ b/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; diff --git a/OpenRA.Game/Support/PerfTimer.cs b/OpenRA.Game/Support/PerfTimer.cs index 29043b6bb5..05514ba73a 100755 --- a/OpenRA.Game/Support/PerfTimer.cs +++ b/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 int depth; + readonly float thresholdMs; + readonly byte depth; readonly PerfTimer parent; List children; + long ticks; static ThreadLocal Parent = new ThreadLocal(); // Tree settings - const int MaxWidth = 60, Digits = 6; - const int MaxIndentedLabel = MaxWidth - Digits; + const int Digits = 6; 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(); @@ -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)); - } - - static string GetOneLiner(string indentation, string label) - { - return string.Concat(indentation, SetLength(label, MaxIndentedLabel - indentation.Length)); + return string.Concat(new string(' ', Digits + FormatSeperation.Length), indentation, label); } static string GetFooter(string indentation) { - return string.Concat(indentation, new string('-', MaxIndentedLabel - 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); + return string.Concat(indentation, new string('-', Math.Max(15, 50 - indentation.Length))); } string Indentation diff --git a/OpenRA.Game/Traits/Util.cs b/OpenRA.Game/Traits/Util.cs index b09d77ad1f..5acc1fc6d4 100644 --- a/OpenRA.Game/Traits/Util.cs +++ b/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; - - using (new PerfTimer("[{0}] Activity: {1}".F(Game.LocalTick, prev), (int)Game.Settings.Debug.LongTickThreshold.TotalMilliseconds)) - act = act.Tick(self); - + act = act.Tick(self); + var current = Stopwatch.GetTimestamp(); + if (current - start > longTickThresholdInStopwatchTicks) + { + PerfTimer.LogLongTick(start, current, "Activity", prev); + start = Stopwatch.GetTimestamp(); + } + else + { + start = current; + } if (prev == act) break; } - return act; } diff --git a/OpenRA.Game/World.cs b/OpenRA.Game/World.cs index c7cf404a55..4c3d4ce498 100644 --- a/OpenRA.Game/World.cs +++ b/OpenRA.Game/World.cs @@ -244,9 +244,9 @@ namespace OpenRA foreach (var a in actors) a.Tick(); - ActorsWithTrait().DoTimed(x => x.Trait.Tick(x.Actor), "Trait", Game.Settings.Debug.LongTickThreshold); + ActorsWithTrait().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) diff --git a/OpenRA.Game/WorldUtils.cs b/OpenRA.Game/WorldUtils.cs index 90cce2b55e..46697c576d 100644 --- a/OpenRA.Game/WorldUtils.cs +++ b/OpenRA.Game/WorldUtils.cs @@ -172,13 +172,28 @@ namespace OpenRA } } - public static void DoTimed(this IEnumerable e, Action a, string text, TimeSpan time) + public static void DoTimed(this IEnumerable e, Action 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)) - a(x); - }); + var start = Stopwatch.GetTimestamp(); + 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 )