Merge pull request #5184 from pavlos256/loading-perf

Loading performance measurements

OpenRA.Game/Game.cs

@@ -246,10 +246,16 @@ namespace OpenRA
 		{
 			BeforeGameStart();
 
-			var map = modData.PrepareMap(mapUID);
+			Map map;
+			using (new PerfTimer("PrepareMap"))
+				map = modData.PrepareMap(mapUID);
+			using (new PerfTimer("NewWorld"))
+			{
 				orderManager.world = new World(modData.Manifest, map, orderManager, isShellmap);
 				orderManager.world.Timestep = Timestep;
+			}
 			worldRenderer = new WorldRenderer(orderManager.world);
+			using (new PerfTimer("LoadComplete"))
 				orderManager.world.LoadComplete(worldRenderer);
 
 			if (orderManager.GameStarted)
@@ -385,6 +391,7 @@ namespace OpenRA
 			modData = new ModData(mod);
 			Renderer.InitializeFonts(modData.Manifest);
 			modData.InitializeLoaders();
+			using (new PerfTimer("LoadMaps"))
 				modData.MapCache.LoadMaps();
 
 			PerfHistory.items["render"].hasNormalTick = false;
@@ -436,7 +443,10 @@ namespace OpenRA
 
 		public static void LoadShellMap()
 		{
-			StartGame(ChooseShellmap(), true);
+			var shellmap = ChooseShellmap();
+
+			using (new PerfTimer("StartGame"))
+				StartGame(shellmap, true);
 		}
 
 		static string ChooseShellmap()
@@ -478,7 +488,7 @@ namespace OpenRA
 
 					Tick(orderManager);
 
-					var waitTime = Math.Min(idealFrameTime - sw.ElapsedTime(), 1);
+					var waitTime = Math.Min(idealFrameTime - sw.Elapsed.TotalSeconds, 1);
 					if (waitTime > 0)
 						System.Threading.Thread.Sleep(TimeSpan.FromSeconds(waitTime));
 				}

OpenRA.Game/Map/Map.cs

@@ -431,13 +431,20 @@ namespace OpenRA
 		string ComputeHash()
 		{
 			// UID is calculated by taking an SHA1 of the yaml and binary data
-			// Read the relevant data into a buffer
-			var data = Container.GetContent("map.yaml").ReadAllBytes()
-				.Concat(Container.GetContent("map.bin").ReadAllBytes()).ToArray();
+
+			using (var ms = new MemoryStream())
+			{
+				// Read the relevant data into the buffer
+				using (var s = Container.GetContent("map.yaml"))
+					s.CopyTo(ms);
+				using (var s = Container.GetContent("map.bin"))
+					s.CopyTo(ms);
 
 				// Take the SHA1
+				ms.Seek(0, SeekOrigin.Begin);
 				using (var csp = SHA1.Create())
-				return new string(csp.ComputeHash(data).SelectMany(a => a.ToString("x2")).ToArray());
+					return new string(csp.ComputeHash(ms).SelectMany(a => a.ToString("x2")).ToArray());
+			}
 		}
 
 		public void MakeDefaultPlayers()

OpenRA.Game/Map/MapCache.cs

@@ -46,11 +46,14 @@ namespace OpenRA
 			foreach (var path in paths)
 			{
 				try
+				{
+					using (new Support.PerfTimer(path))
 					{
 						var map = new Map(path, manifest.Mod.Id);
 						if (manifest.MapCompatibility.Contains(map.RequiresMod))
 							previews[map.Uid].UpdateFromMap(map);
 					}
+				}
 				catch (Exception e)
 				{
 					Console.WriteLine("Failed to load map: {0}", path);

OpenRA.Game/ModData.cs

@@ -118,11 +118,15 @@ 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("LoadRules"))
 				Rules.LoadRules(Manifest, map);
 			SpriteLoader = new SpriteLoader(Rules.TileSets[map.Tileset].Extensions, SheetBuilder);
 
+			using (new Support.PerfTimer("SequenceProvider.Initialize"))
+			{
 				// TODO: Don't load the sequences for assets that are not used in this tileset. Maybe use the existing EditorTilesetFilters.
 				SequenceProvider.Initialize(Manifest.Sequences, map.Sequences);
+			}
 			VoxelProvider.Initialize(Manifest.VoxelSequences, map.VoxelSequences);
 			return map;
 		}

OpenRA.Game/OpenRA.Game.csproj

@@ -293,7 +293,7 @@
     <Compile Include="Primitives\Set.cs" />
     <Compile Include="Support\Log.cs" />
     <Compile Include="Support\Stopwatch.cs" />
-    <Compile Include="Support\Timer.cs" />
+    <Compile Include="Support\PerfTimer.cs" />
     <Compile Include="Exts.cs" />
     <Compile Include="Hotkey.cs" />
     <Compile Include="Keycode.cs" />

OpenRA.Game/Settings.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2013 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -71,7 +71,7 @@ namespace OpenRA
 		public bool BotDebug = false;
 		public bool PerfText = false;
 		public bool PerfGraph = false;
-		public float LongTickThreshold = 0.001f;
+		public TimeSpan LongTickThreshold = TimeSpan.FromMilliseconds(1d);
 		public bool SanityCheckUnsyncedCode = false;
 		public int Samples = 25;
 		public bool IgnoreVersionMismatch = false;

OpenRA.Game/Support/Log.cs

@@ -46,6 +46,12 @@ namespace OpenRA
 		{
 			if (Channels.ContainsKey(channelName)) return;
 
+			if (string.IsNullOrEmpty(baseFilename))
+			{
+				Channels.Add(channelName, new ChannelInfo());
+				return;
+			}
+
 			foreach (var filename in FilenamesForChannel(channelName, baseFilename))
 				try
 				{
@@ -70,6 +76,9 @@ namespace OpenRA
 			if (!Channels.TryGetValue(channel, out info))
 				throw new Exception("Tried logging to non-existant channel " + channel);
 
+			if (info.Writer == null)
+				return;
+
 			info.Writer.WriteLine(format, args);
 		}
 	}

OpenRA.Game/Support/PerfHistory.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2011 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -116,7 +116,7 @@ namespace OpenRA.Support
 
 		public void Dispose()
 		{
-			PerfHistory.Increment(Item, sw.ElapsedTime() * 1000);
+			PerfHistory.Increment(Item, sw.Elapsed.TotalMilliseconds);
 		}
 	}
 }

OpenRA.Game/Support/PerfTimer.cs

@@ -0,0 +1,117 @@
+#region Copyright & License Information
+/*
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
+ * This file is part of OpenRA, which is free software. It is made
+ * available to you under the terms of the GNU General Public License
+ * as published by the Free Software Foundation. For more information,
+ * see COPYING.
+ */
+#endregion
+
+using System;
+using System.Linq;
+using System.Threading;
+
+namespace OpenRA.Support
+{
+	public class PerfTimer : IDisposable
+	{
+		readonly Stopwatch sw = new Stopwatch();
+		readonly string Name;
+
+		//
+		// Hacks to give the output a tree-like structure
+		//
+		static ThreadLocal<int> depth = new ThreadLocal<int>();
+		static ThreadLocal<string> prevHeader = new ThreadLocal<string>();
+		const int MaxWidth = 60, Digits = 6;
+		const int MaxIndentedLabel = MaxWidth - Digits;
+		const string IndentationString = "|   ";
+		readonly string FormatString = "{0," + MaxIndentedLabel + "} {1," + Digits + "} ms";
+
+		public PerfTimer(string name)
+		{
+			if (prevHeader.Value != null)
+			{
+				Log.Write("perf", prevHeader.Value);
+				prevHeader.Value = null;
+			}
+
+			this.Name = name;
+
+			prevHeader.Value = GetHeader(Indentation, this.Name);
+			depth.Value++;
+		}
+
+		public void Dispose()
+		{
+			depth.Value--;
+
+			string s;
+
+			if (prevHeader.Value == null)
+			{
+				s = GetFooter(Indentation);
+			}
+			else
+			{
+				s = GetOneLiner(Indentation, this.Name);
+				prevHeader.Value = null;
+			}
+
+			Log.Write("perf", FormatString, s, Math.Round(this.sw.Elapsed.TotalMilliseconds));
+		}
+
+		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));
+		}
+
+		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);
+		}
+
+		static string Indentation
+		{
+			get
+			{
+				var d = depth.Value;
+				if (d == 1)
+					return IndentationString;
+				else if (d <= 0)
+					return string.Empty;
+				else
+					return string.Concat(Enumerable.Repeat(IndentationString, depth.Value));
+			}
+		}
+	}
+}

OpenRA.Game/Support/Stopwatch.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2011 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -13,14 +13,15 @@ namespace OpenRA.Support
 	public class Stopwatch
 	{
 		System.Diagnostics.Stopwatch sw;
-		public Stopwatch ()
+
+		public Stopwatch()
 		{
 			Reset();
 		}
 
-		public double ElapsedTime()
+		public System.TimeSpan Elapsed
 		{
-			return sw.Elapsed.TotalMilliseconds / 1000.0;
+			get { return this.sw.Elapsed; }
 		}
 
 		public void Reset()

OpenRA.Game/Support/Timer.cs

@@ -1,27 +0,0 @@
-#region Copyright & License Information
-/*
- * Copyright 2007-2011 The OpenRA Developers (see AUTHORS)
- * This file is part of OpenRA, which is free software. It is made
- * available to you under the terms of the GNU General Public License
- * as published by the Free Software Foundation. For more information,
- * see COPYING.
- */
-#endregion
-
-namespace OpenRA.Support
-{
-	public static class Timer
-	{
-		static Stopwatch sw = new Stopwatch();
-		static double lastTime = 0;
-
-		public static void Time( string message )
-		{
-			var time = sw.ElapsedTime();
-			var dt = time - lastTime;
-			if( dt > 0.0001 )
-				Log.Write("perf", message, dt );
-			lastTime = time;
-		}
-	}
-}

OpenRA.Game/Traits/Util.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2013 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -83,9 +83,9 @@ namespace OpenRA.Traits
 
 				var sw = new Stopwatch();
 				act = act.Tick(self);
-				var dt = sw.ElapsedTime();
+				var dt = sw.Elapsed;
 				if (dt > Game.Settings.Debug.LongTickThreshold)
-					Log.Write("perf", "[{2}] Activity: {0} ({1:0.000} ms)", prev, dt * 1000, Game.LocalTick);
+					Log.Write("perf", "[{2}] Activity: {0} ({1:0.000} ms)", prev, dt.TotalMilliseconds, Game.LocalTick);
 
 				if (prev == act)
 					break;

OpenRA.Game/World.cs

@@ -148,8 +148,11 @@ namespace OpenRA
 		public void LoadComplete(WorldRenderer wr)
 		{
 			foreach (var wlh in WorldActor.TraitsImplementing<IWorldLoaded>())
+			{
+				using (new Support.PerfTimer(wlh.GetType().Name + ".WorldLoaded"))
 					wlh.WorldLoaded(this, wr);
 			}
+		}
 
 		public Actor CreateActor(string name, TypeDictionary initDict)
 		{

OpenRA.Game/WorldUtils.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2011 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -171,17 +171,17 @@ namespace OpenRA
 			}
 		}
 
-		public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text, double time)
+		public static void DoTimed<T>(this IEnumerable<T> e, Action<T> a, string text, TimeSpan time)
 		{
 			var sw = new Stopwatch();
 
 			e.Do(x =>
 			{
-				var t = sw.ElapsedTime();
+				var t = sw.Elapsed;
 				a(x);
-				var dt = sw.ElapsedTime() - t;
+				var dt = sw.Elapsed - t;
 				if (dt > time)
-					Log.Write("perf", text, x, dt * 1000, Game.LocalTick);
+					Log.Write("perf", text, x, dt.TotalMilliseconds, Game.LocalTick);
 			});
 		}
 

OpenRA.Lint/YamlChecker.cs

@@ -11,6 +11,7 @@
 using System;
 using System.Collections.Generic;
 using System.Linq;
+using System.IO;
 using OpenRA.FileSystem;
 using OpenRA.Traits;
 
@@ -41,6 +42,8 @@ namespace OpenRA.Lint
 
 			try
 			{
+				Log.AddChannel("perf", null);
+
 				var options = args.Where(a => a.StartsWith("-"));
 				var mod = args.Where(a => !options.Contains(a)).First();
 				var map = args.Where(a => !options.Contains(a)).Skip(1).FirstOrDefault();

OpenRA.Mods.Cnc/CncLoadScreen.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2011 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -76,7 +76,7 @@ namespace OpenRA.Mods.Cnc
 
 		public void Display()
 		{
-			if (r == null || loadTimer.ElapsedTime() < 0.25)
+			if (r == null || loadTimer.Elapsed.TotalSeconds < 0.25)
 				return;
 
 			loadTimer.Reset();

OpenRA.Mods.RA/DefaultLoadScreen.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2013 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -55,7 +55,7 @@ namespace OpenRA.Mods.RA
 				return;
 
 			// Update text at most every 0.5 seconds
-			if (lastUpdate.ElapsedTime() < 0.5)
+			if (lastUpdate.Elapsed.TotalSeconds < 0.5)
 				return;
 
 			if (r.Fonts == null)

OpenRA.Mods.RA/World/DomainIndex.cs

@@ -1,6 +1,6 @@
 #region Copyright & License Information
 /*
- * Copyright 2007-2013 The OpenRA Developers (see AUTHORS)
+ * Copyright 2007-2014 The OpenRA Developers (see AUTHORS)
  * This file is part of OpenRA, which is free software. It is made
  * available to you under the terms of the GNU General Public License
  * as published by the Free Software Foundation. For more information,
@@ -241,7 +241,7 @@ namespace OpenRA.Mods.RA
 				domain += 1;
 			}
 
-			Log.Write("debug", "{0}: Found {1} domains.  Took {2} s", map.Title, domain-1, timer.ElapsedTime());
+			Log.Write("debug", "{0}: Found {1} domains.  Took {2} s", map.Title, domain-1, timer.Elapsed.TotalSeconds);
 		}
 	}
 }