#region File Description //----------------------------------------------------------------------------- // TimeRuler.cs // // Microsoft XNA Community Game Platform // Copyright (C) Microsoft Corporation. All rights reserved. //----------------------------------------------------------------------------- #endregion #region Using Statements using System; using System.Collections.Generic; using System.Diagnostics; using System.Threading; using System.Text; using Microsoft.Xna.Framework; using Microsoft.Xna.Framework.Graphics; #endregion namespace PerformanceMeasuring.GameDebugTools { /// /// Realtime CPU measuring tool /// /// /// You can visually find bottle neck, and know how much you can put more CPU jobs /// by using this tool. /// Because of this is real time profile, you can find glitches in the game too. /// /// TimeRuler provide the following features: /// * Up to 8 bars (Configurable) /// * Change colors for each markers /// * Marker logging. /// * It won't even generate BeginMark/EndMark method calls when you got rid of the /// TRACE constant. /// * It supports up to 32 (Configurable) nested BeginMark method calls. /// * Multithreaded safe /// * Automatically changes display frames based on frame duration. /// /// How to use: /// Added TimerRuler instance to Game.Components and call timerRuler.StartFrame in /// top of the Game.Update method. /// /// Then, surround the code that you want measure by BeginMark and EndMark. /// /// timeRuler.BeginMark( "Update", Color.Blue ); /// // process that you want to measure. /// timerRuler.EndMark( "Update" ); /// /// Also, you can specify bar index of marker (default value is 0) /// /// timeRuler.BeginMark( 1, "Update", Color.Blue ); /// /// All profiling methods has CondionalAttribute with "TRACE". /// If you not specified "TRACE" constant, it doesn't even generate /// method calls for BeginMark/EndMark. /// So, don't forget remove "TRACE" constant when you release your game. /// /// public class TimeRuler : DrawableGameComponent { #region Constants /// /// Max bar count. /// const int MaxBars = 8; /// /// Maximum sample number for each bar. /// const int MaxSamples = 256; /// /// Maximum nest calls for each bar. /// const int MaxNestCall = 32; /// /// Maximum display frames. /// const int MaxSampleFrames = 4; /// /// Duration (in frame count) for take snap shot of log. /// const int LogSnapDuration = 120; /// /// Height(in pixels) of bar. /// const int BarHeight = 8; /// /// Padding(in pixels) of bar. /// const int BarPadding = 2; /// /// Delay frame count for auto display frame adjustment. /// const int AutoAdjustDelay = 30; #endregion #region Properties /// /// Gets/Set log display or no. /// public bool ShowLog { get; set; } /// /// Gets/Sets target sample frames. /// public int TargetSampleFrames { get; set; } /// /// Gets/Sets TimeRuler rendering position. /// public Vector2 Position { get { return position; } set { position = value; } } /// /// Gets/Sets timer ruler width. /// public int Width { get; set; } #endregion #region Fields #if TRACE /// /// Marker structure. /// private struct Marker { public int MarkerId; public float BeginTime; public float EndTime; public Color Color; } /// /// Collection of markers. /// private class MarkerCollection { // Marker collection. public Marker[] Markers = new Marker[MaxSamples]; public int MarkCount; // Marker nest information. public int[] MarkerNests = new int[MaxNestCall]; public int NestCount; } /// /// Frame logging information. /// private class FrameLog { public MarkerCollection[] Bars; public FrameLog() { // Initialize markers. Bars = new MarkerCollection[MaxBars]; for (int i = 0; i < MaxBars; ++i) Bars[i] = new MarkerCollection(); } } /// /// Marker information /// private class MarkerInfo { // Name of marker. public string Name; // Marker log. public MarkerLog[] Logs = new MarkerLog[MaxBars]; public MarkerInfo(string name) { Name = name; } } /// /// Marker log information. /// private struct MarkerLog { public float SnapMin; public float SnapMax; public float SnapAvg; public float Min; public float Max; public float Avg; public int Samples; public Color Color; public bool Initialized; } // Reference of debug manager. DebugManager debugManager; // Logs for each frames. FrameLog[] logs; // Previous frame log. FrameLog prevLog; // Current log. FrameLog curLog; // Current frame count. int frameCount; // Stopwatch for measure the time. Stopwatch stopwatch = new Stopwatch(); // Marker information array. List markers = new List(); // Dictionary that maps from marker name to marker id. Dictionary markerNameToIdMap = new Dictionary(); // Display frame adjust counter. int frameAdjust; // Current display frame count. int sampleFrames; // Marker log string. StringBuilder logString = new StringBuilder(512); // You want to call StartFrame at beginning of Game.Update method. // But Game.Update gets calls multiple time when game runs slow in fixed time step mode. // In this case, we should ignore StartFrame call. // To do this, we just keep tracking of number of StartFrame calls until Draw gets called. int updateCount; #endif // TimerRuler draw position. Vector2 position; #endregion #region Initialization public TimeRuler(Game game) : base(game) { // Add this as a service. Game.Services.AddService(typeof(TimeRuler), this); } public override void Initialize() { #if TRACE debugManager = Game.Services.GetService(typeof(DebugManager)) as DebugManager; if (debugManager == null) throw new InvalidOperationException("DebugManager is not registered."); // Add "tr" command if DebugCommandHost is registered. IDebugCommandHost host = Game.Services.GetService(typeof(IDebugCommandHost)) as IDebugCommandHost; if (host != null) { host.RegisterCommand("tr", "TimeRuler", this.CommandExecute); this.Visible = true; } // Initialize Parameters. logs = new FrameLog[2]; for (int i = 0; i < logs.Length; ++i) logs[i] = new FrameLog(); sampleFrames = TargetSampleFrames = 1; // Time-Ruler's update method doesn't need to get called. this.Enabled = false; #endif base.Initialize(); } protected override void LoadContent() { Width = (int)(GraphicsDevice.Viewport.Width * 0.8f); Layout layout = new Layout(GraphicsDevice.Viewport); position = layout.Place(new Vector2(Width, BarHeight), 0, 0.01f, Alignment.BottomCenter); base.LoadContent(); } #if TRACE /// /// 'tr' command execution. /// void CommandExecute(IDebugCommandHost host, string command, IList arguments) { bool previousVisible = Visible; if (arguments.Count == 0) Visible = !Visible; char[] subArgSeparator = new[] { ':' }; foreach (string orgArg in arguments) { string arg = orgArg.ToLower(); string[] subargs = arg.Split(subArgSeparator); switch (subargs[0]) { case "on": Visible = true; break; case "off": Visible = false; break; case "reset": ResetLog(); break; case "log": if (subargs.Length > 1) { if (String.Compare(subargs[1], "on") == 0) ShowLog = true; if (String.Compare(subargs[1], "off") == 0) ShowLog = false; } else { ShowLog = !ShowLog; } break; case "frame": int a = Int32.Parse(subargs[1]); a = Math.Max(a, 1); a = Math.Min(a, MaxSampleFrames); TargetSampleFrames = a; break; case "/?": case "--help": host.Echo("tr [log|on|off|reset|frame]"); host.Echo("Options:"); host.Echo(" on Display TimeRuler."); host.Echo(" off Hide TimeRuler."); host.Echo(" log Show/Hide marker log."); host.Echo(" reset Reset marker log."); host.Echo(" frame:sampleFrames"); host.Echo(" Change target sample frame count"); break; default: break; } } // Reset update count when Visible state changed. if (Visible != previousVisible) { Interlocked.Exchange(ref updateCount, 0); } } #endif #endregion #region Measuring methods /// /// Start new frame. /// [Conditional("TRACE")] public void StartFrame() { #if TRACE lock (this) { // We skip reset frame when this method gets called multiple times. int count = Interlocked.Increment(ref updateCount); if (Visible && (1 < count && count < MaxSampleFrames)) return; // Update current frame log. prevLog = logs[frameCount++ & 0x1]; curLog = logs[frameCount & 0x1]; float endFrameTime = (float)stopwatch.Elapsed.TotalMilliseconds; // Update marker and create a log. for (int barIdx = 0; barIdx < prevLog.Bars.Length; ++barIdx) { MarkerCollection prevBar = prevLog.Bars[barIdx]; MarkerCollection nextBar = curLog.Bars[barIdx]; // Re-open marker that didn't get called EndMark in previous frame. for (int nest = 0; nest < prevBar.NestCount; ++nest) { int markerIdx = prevBar.MarkerNests[nest]; prevBar.Markers[markerIdx].EndTime = endFrameTime; nextBar.MarkerNests[nest] = nest; nextBar.Markers[nest].MarkerId = prevBar.Markers[markerIdx].MarkerId; nextBar.Markers[nest].BeginTime = 0; nextBar.Markers[nest].EndTime = -1; nextBar.Markers[nest].Color = prevBar.Markers[markerIdx].Color; } // Update marker log. for (int markerIdx = 0; markerIdx < prevBar.MarkCount; ++markerIdx) { float duration = prevBar.Markers[markerIdx].EndTime - prevBar.Markers[markerIdx].BeginTime; int markerId = prevBar.Markers[markerIdx].MarkerId; MarkerInfo m = markers[markerId]; m.Logs[barIdx].Color = prevBar.Markers[markerIdx].Color; if (!m.Logs[barIdx].Initialized) { // First frame process. m.Logs[barIdx].Min = duration; m.Logs[barIdx].Max = duration; m.Logs[barIdx].Avg = duration; m.Logs[barIdx].Initialized = true; } else { // Process after first frame. m.Logs[barIdx].Min = Math.Min(m.Logs[barIdx].Min, duration); m.Logs[barIdx].Max = Math.Min(m.Logs[barIdx].Max, duration); m.Logs[barIdx].Avg += duration; m.Logs[barIdx].Avg *= 0.5f; if (m.Logs[barIdx].Samples++ >= LogSnapDuration) { m.Logs[barIdx].SnapMin = m.Logs[barIdx].Min; m.Logs[barIdx].SnapMax = m.Logs[barIdx].Max; m.Logs[barIdx].SnapAvg = m.Logs[barIdx].Avg; m.Logs[barIdx].Samples = 0; } } } nextBar.MarkCount = prevBar.NestCount; nextBar.NestCount = prevBar.NestCount; } // Start measuring. stopwatch.Reset(); stopwatch.Start(); } #endif } /// /// Start measure time. /// /// name of marker. /// color/param> [Conditional("TRACE")] public void BeginMark(string markerName, Color color) { #if TRACE BeginMark(0, markerName, color); #endif } /// /// Start measure time. /// /// index of bar /// name of marker. /// color/param> [Conditional("TRACE")] public void BeginMark(int barIndex, string markerName, Color color) { #if TRACE lock (this) { if (barIndex < 0 || barIndex >= MaxBars) throw new ArgumentOutOfRangeException("barIndex"); MarkerCollection bar = curLog.Bars[barIndex]; if (bar.MarkCount >= MaxSamples) { throw new OverflowException( "Exceeded sample count.\n" + "Either set larger number to TimeRuler.MaxSmpale or" + "lower sample count."); } if (bar.NestCount >= MaxNestCall) { throw new OverflowException( "Exceeded nest count.\n" + "Either set larget number to TimeRuler.MaxNestCall or" + "lower nest calls."); } // Gets registered marker. int markerId; if (!markerNameToIdMap.TryGetValue(markerName, out markerId)) { // Register this if this marker is not registered. markerId = markers.Count; markerNameToIdMap.Add(markerName, markerId); markers.Add(new MarkerInfo(markerName)); } // Start measuring. bar.MarkerNests[bar.NestCount++] = bar.MarkCount; // Fill marker parameters. bar.Markers[bar.MarkCount].MarkerId = markerId; bar.Markers[bar.MarkCount].Color = color; bar.Markers[bar.MarkCount].BeginTime = (float)stopwatch.Elapsed.TotalMilliseconds; bar.Markers[bar.MarkCount].EndTime = -1; bar.MarkCount++; } #endif } /// /// End measuring. /// /// Name of marker. [Conditional("TRACE")] public void EndMark(string markerName) { #if TRACE EndMark(0, markerName); #endif } /// /// End measuring. /// /// Index of bar. /// Name of marker. [Conditional("TRACE")] public void EndMark(int barIndex, string markerName) { #if TRACE lock (this) { if (barIndex < 0 || barIndex >= MaxBars) throw new ArgumentOutOfRangeException("barIndex"); MarkerCollection bar = curLog.Bars[barIndex]; if (bar.NestCount <= 0) { throw new InvalidOperationException( "Call BeingMark method before call EndMark method."); } int markerId; if (!markerNameToIdMap.TryGetValue(markerName, out markerId)) { throw new InvalidOperationException( String.Format("Maker '{0}' is not registered." + "Make sure you specifed same name as you used for BeginMark" + " method.", markerName)); } int markerIdx = bar.MarkerNests[--bar.NestCount]; if (bar.Markers[markerIdx].MarkerId != markerId) { throw new InvalidOperationException( "Incorrect call order of BeginMark/EndMark method." + "You call it like BeginMark(A), BeginMark(B), EndMark(B), EndMark(A)" + " But you can't call it like " + "BeginMark(A), BeginMark(B), EndMark(A), EndMark(B)."); } bar.Markers[markerIdx].EndTime = (float)stopwatch.Elapsed.TotalMilliseconds; } #endif } /// /// Get average time of given bar index and marker name. /// /// Index of bar /// name of marker /// average spending time in ms. public float GetAverageTime(int barIndex, string markerName) { #if TRACE if (barIndex < 0 || barIndex >= MaxBars) throw new ArgumentOutOfRangeException("barIndex"); float result = 0; int markerId; if (markerNameToIdMap.TryGetValue(markerName, out markerId)) result = markers[markerId].Logs[barIndex].Avg; return result; #else return 0f; #endif } /// /// Reset marker log. /// [Conditional("TRACE")] public void ResetLog() { #if TRACE lock (this) { foreach (MarkerInfo markerInfo in markers) { for (int i = 0; i < markerInfo.Logs.Length; ++i) { markerInfo.Logs[i].Initialized = false; markerInfo.Logs[i].SnapMin = 0; markerInfo.Logs[i].SnapMax = 0; markerInfo.Logs[i].SnapAvg = 0; markerInfo.Logs[i].Min = 0; markerInfo.Logs[i].Max = 0; markerInfo.Logs[i].Avg = 0; markerInfo.Logs[i].Samples = 0; } } } #endif } #endregion #region Draw public override void Draw(GameTime gameTime) { Draw(position, Width); base.Draw(gameTime); } [Conditional("TRACE")] public void Draw(Vector2 position, int width) { #if TRACE // Reset update count. Interlocked.Exchange(ref updateCount, 0); // Gets SpriteBatch, SpriteFont, and WhiteTexture from DebugManager. SpriteBatch spriteBatch = debugManager.SpriteBatch; SpriteFont font = debugManager.DebugFont; Texture2D texture = debugManager.WhiteTexture; // Adjust size and position based of number of bars we should draw. int height = 0; float maxTime = 0; foreach (MarkerCollection bar in prevLog.Bars) { if (bar.MarkCount > 0) { height += BarHeight + BarPadding * 2; maxTime = Math.Max(maxTime, bar.Markers[bar.MarkCount - 1].EndTime); } } // Auto display frame adjustment. // For example, if the entire process of frame doesn't finish in less than 16.6ms // thin it will adjust display frame duration as 33.3ms. const float frameSpan = 1.0f / 60.0f * 1000f; float sampleSpan = (float)sampleFrames * frameSpan; if (maxTime > sampleSpan) frameAdjust = Math.Max(0, frameAdjust) + 1; else frameAdjust = Math.Min(0, frameAdjust) - 1; if (Math.Abs(frameAdjust) > AutoAdjustDelay) { sampleFrames = Math.Min(MaxSampleFrames, sampleFrames); sampleFrames = Math.Max(TargetSampleFrames, (int)(maxTime / frameSpan) + 1); frameAdjust = 0; } // Compute factor that converts from ms to pixel. float msToPs = (float)width / sampleSpan; // Draw start position. int startY = (int)position.Y - (height - BarHeight); // Current y position. int y = startY; spriteBatch.Begin(); // Draw transparency background. Rectangle rc = new Rectangle((int)position.X, y, width, height); spriteBatch.Draw(texture, rc, new Color(0, 0, 0, 128)); // Draw markers for each bars. rc.Height = BarHeight; foreach (MarkerCollection bar in prevLog.Bars) { rc.Y = y + BarPadding; if (bar.MarkCount > 0) { for (int j = 0; j < bar.MarkCount; ++j) { float bt = bar.Markers[j].BeginTime; float et = bar.Markers[j].EndTime; int sx = (int)(position.X + bt * msToPs); int ex = (int)(position.X + et * msToPs); rc.X = sx; rc.Width = Math.Max(ex - sx, 1); spriteBatch.Draw(texture, rc, bar.Markers[j].Color); } } y += BarHeight + BarPadding; } // Draw grid lines. // Each grid represents ms. rc = new Rectangle((int)position.X, (int)startY, 1, height); for (float t = 1.0f; t < sampleSpan; t += 1.0f) { rc.X = (int)(position.X + t * msToPs); spriteBatch.Draw(texture, rc, Color.Gray); } // Draw frame grid. for (int i = 0; i <= sampleFrames; ++i) { rc.X = (int)(position.X + frameSpan * (float)i * msToPs); spriteBatch.Draw(texture, rc, Color.White); } // Draw log. if (ShowLog) { // Generate log string. y = startY - font.LineSpacing; logString.Length = 0; foreach (MarkerInfo markerInfo in markers) { for (int i = 0; i < MaxBars; ++i) { if (markerInfo.Logs[i].Initialized) { if (logString.Length > 0) logString.Append("\n"); logString.Append(" Bar "); logString.AppendNumber(i); logString.Append(" "); logString.Append(markerInfo.Name); logString.Append(" Avg.:"); logString.AppendNumber(markerInfo.Logs[i].SnapAvg); logString.Append("ms "); y -= font.LineSpacing; } } } // Compute background size and draw it. Vector2 size = font.MeasureString(logString); rc = new Rectangle((int)position.X, (int)y, (int)size.X + 12, (int)size.Y); spriteBatch.Draw(texture, rc, new Color(0, 0, 0, 128)); // Draw log string. spriteBatch.DrawString(font, logString, new Vector2(position.X + 12, y), Color.White); // Draw log color boxes. y += (int)((float)font.LineSpacing * 0.3f); rc = new Rectangle((int)position.X + 4, y, 10, 10); Rectangle rc2 = new Rectangle((int)position.X + 5, y + 1, 8, 8); foreach (MarkerInfo markerInfo in markers) { for (int i = 0; i < MaxBars; ++i) { if (markerInfo.Logs[i].Initialized) { rc.Y = y; rc2.Y = y + 1; spriteBatch.Draw(texture, rc, Color.White); spriteBatch.Draw(texture, rc2, markerInfo.Logs[i].Color); y += font.LineSpacing; } } } } spriteBatch.End(); #endif } #endregion } }