From df0d1360dd50038789ae4fc782ad01d2a0ab4909 Mon Sep 17 00:00:00 2001 From: Pavlos Touboulidis Date: Wed, 21 May 2014 17:18:53 +0300 Subject: [PATCH 1/2] 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); }); } From 531338a955b71f04dcbef8b4cfa61791e27aab7b Mon Sep 17 00:00:00 2001 From: Pavlos Touboulidis Date: Wed, 21 May 2014 22:56:59 +0300 Subject: [PATCH 2/2] Preload sequences and fix #5382 --- OpenRA.Game/FileSystem/GlobalFileSystem.cs | 23 +++++++++++++++++----- OpenRA.Game/Graphics/SequenceProvider.cs | 22 +++++++++++++++++++-- OpenRA.Game/ModData.cs | 4 +++- 3 files changed, 41 insertions(+), 8 deletions(-) diff --git a/OpenRA.Game/FileSystem/GlobalFileSystem.cs b/OpenRA.Game/FileSystem/GlobalFileSystem.cs index f7eeb62db9..45ca6af2bf 100644 --- a/OpenRA.Game/FileSystem/GlobalFileSystem.cs +++ b/OpenRA.Game/FileSystem/GlobalFileSystem.cs @@ -168,18 +168,27 @@ namespace OpenRA.FileSystem public static Stream Open(string filename) { return OpenWithExts(filename, ""); } public static Stream OpenWithExts(string filename, params string[] exts) + { + Stream s; + if (!TryOpenWithExts(filename, exts, out s)) + throw new FileNotFoundException("File not found: {0}".F(filename), filename); + + return s; + } + + public static bool TryOpenWithExts(string filename, string[] exts, out Stream s) { if (filename.IndexOfAny(new char[] { '/', '\\' }) == -1) { foreach (var ext in exts) { - var s = GetFromCache(PackageHashType.Classic, filename + ext); + s = GetFromCache(PackageHashType.Classic, filename + ext); if (s != null) - return s; + return true; s = GetFromCache(PackageHashType.CRC32, filename + ext); if (s != null) - return s; + return true; } } @@ -191,10 +200,14 @@ namespace OpenRA.FileSystem .FirstOrDefault(); if (folder != null) - return folder.GetContent(filename + ext); + { + s = folder.GetContent(filename + ext); + return true; + } } - throw new FileNotFoundException("File not found: {0}".F(filename), filename); + s = null; + return false; } public static bool Exists(string filename) { return MountedFolders.Any(f => f.Exists(filename)); } diff --git a/OpenRA.Game/Graphics/SequenceProvider.cs b/OpenRA.Game/Graphics/SequenceProvider.cs index 1adfa14d19..5ce8d618f4 100644 --- a/OpenRA.Game/Graphics/SequenceProvider.cs +++ b/OpenRA.Game/Graphics/SequenceProvider.cs @@ -58,6 +58,21 @@ namespace OpenRA.Graphics return unitSeq.Value.Keys; } + + public void Preload() + { + foreach (var unitSeq in sequences.Value.Values) + { + try + { + foreach (var seq in unitSeq.Value.Values); + } + catch (FileNotFoundException ex) + { + Log.Write("debug", ex.Message); + } + } + } } public class SequenceCache @@ -100,8 +115,11 @@ namespace OpenRA.Graphics else { t = Exts.Lazy(() => (IReadOnlyDictionary)new ReadOnlyDictionary( - node.Value.NodesDict.ToDictionary(x => x.Key, x => - new Sequence(spriteLoader.Value, node.Key, x.Key, x.Value)))); + node.Value.NodesDict.ToDictionary(x => x.Key, x => + { + using (new Support.PerfTimer("new Sequence(\"{0}\")".F(node.Key), 20)) + return new Sequence(spriteLoader.Value, node.Key, x.Key, x.Value); + }))); sequenceCache.Add(key, t); items.Add(node.Key, t); } diff --git a/OpenRA.Game/ModData.cs b/OpenRA.Game/ModData.cs index 4ad17eaaf7..1716bcd1e5 100644 --- a/OpenRA.Game/ModData.cs +++ b/OpenRA.Game/ModData.cs @@ -134,8 +134,10 @@ namespace OpenRA // Mount map package so custom assets can be used. TODO: check priority. GlobalFileSystem.Mount(GlobalFileSystem.OpenPackage(map.Path, null, int.MaxValue)); - using (new Support.PerfTimer("Map.LoadRules")) + using (new Support.PerfTimer("Map.PreloadRules")) map.PreloadRules(); + using (new Support.PerfTimer("Map.SequenceProvider.Preload")) + map.SequenceProvider.Preload(); VoxelProvider.Initialize(Manifest.VoxelSequences, map.VoxelSequenceDefinitions);