Friday 13 July 2012

Performance Solved

I have just had the oddest result by fixing one problem I have solved another.  As my wife just pointed out normally it works the other way round.  I normally solve one problem and create two other problems!  Not this time. :-)



To monitor performance while I play the game I use some graphs to avoid creating garbage.  These I display at the sides of the screen to show me memory allocations and CPU usage.  The memory bar goes up and eventually I can see garbage being collected with the momentary slow down on the Xbox.



On the other side I have a performance monitor that measures the time that hardware thread one Update and Draw methods take to complete and a third bar that measures the time taken for the Update that runs on hardware thread four.  These are my primary methods.  The graph is in milliseconds (ms) up to 17 and the bar changes colour to red when any result exceeds 16ms (one frame). 


For a long time I have known that looking in some directions causes a noticeable slowdown and the third bar shows red and off the top of the chart!  Visually the screen would stutter because the position of the view was not being updated quickly enough!  It was probably as annoying as the glitch caused by garbage collection.

As I had run out of things to try to get rid of my remaining garbage I decided it was time that I needed to deal with the performance related hiccup to make it feel nicer to play.

After a bit of fiddling I decided I could not guess where the problem was I needed some way to measure it.  I created myself a simple timer.








    ///  

    /// A static timer which displays the duration of a method in the trace output. 

    /// This is NOT thread safe and cannot be nested. 

    ///  

    public class MethodTimer 
        public static System.Diagnostics.Stopwatch Clock = new Stopwatch(); 
        public static TimeSpan StartTime = TimeSpan.Zero; 
 
        ///  

        /// Mark the starting time to measure from. 

        /// This also starts the timer if it is not already running. 

        ///  

        [Conditional("DEBUG")] 
        public static void Start() 
            if (!Clock.IsRunning) 
                Clock.Start(); 
            StartTime = Clock.Elapsed; 
 
        ///  

        /// Output to the trace window if the duration measured is greater than that specified. 

        ///  

        [Conditional("DEBUG")] 
        public static void Stop(string logName, TimeSpan logDurationOver) 
            if (Clock.IsRunning) 
                TimeSpan duration = Clock.Elapsed; 
                duration -= StartTime; 
                if (duration > logDurationOver) 
                    System.Diagnostics.Debug.WriteLine("Method: " + logName + " took " + duration.TotalMilliseconds.ToString() + " milliseconds!"); 
                return
            System.Diagnostics.Debug.WriteLine("The clock was not running when the Stop method was called!"); 
 




I put it either side of a method and get it to log a result if the time that method takes is longer than I expect.

I was surprised how quickly I got it down to one method causing my problem.  I won't go in to detail about the specific method.  It just simply attempted to do far to much every frame to get more accuracy than I needed.  I produced a much quicker but less accurate version.

Now for the great news.  When I tested that on the Xbox not only had my performance problem completely gone but so had ALL of my memory allocations, no garbage collection!  Two in one.

It's not entirely true that all my memory allocations have gone, but as long as you don't make any new sounds (XACT) or respawn there are none and the tiny allocations that do happen from those methods take a very long time before they would trigger the garbage collection :-)

==

Downloads:
'Performance Tools' including the graphs mentioned above:
http://code.google.com/p/xna-game-menu/downloads/list

Update: 27 July 2012
I have just come across an article written a few years ago  suggesting the same method as above:
http://blogs.msdn.com/b/shawnhar/archive/2009/07/07/profiling-with-stopwatch.aspx

2 comments:

Brandon said...

The on-screen diagnostics are quite a clever piece of work, did you use a pre-existing library for the memory watcher, or was that all home-brew?

Great blog overall, I love following the creative process on projects like these. Keep up the good work!

John C Brown said...

I created the performance graphs myself. I've tidied up the code and added a few more comments. The link to download the source code is now included above.

Regards