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

Memory Allocations

A couple of weeks ago I mentioned that I had managed to work out how to run the CLR Profiler with XNA 4.  I now understand enough to work out what the results mean.  At least enough to track back to the parts of my code that are allocating memory during the game and therefore creating garbage to be cleaned up!

I have not finished getting rid of all the allocations yet but I was able to run through some testing on the Xbox 360 without the Garbage Collector triggering too frequently.

I found the CLR Profiler daunting at first but once you know which bits to ignore it's not so bad.

For my purposes all I need is the Allocation Graph button.

There's a tiny bit to know before you'll get anything at all and that is to make sure the 'Allocations' Profile: is ticked before unticking 'Profiling active'.  The 'Calls' profile collects a lot more data and as far as I can tell does not help with finding memory allocations.

At the point in the game where you want to start logging from simply Alt-Tab out of your game and in to the CLR Profiler window to tick the 'Profiling active' box.  Then Alt-Tab back to the game.  If you do it the other way round and try and tick the Profile: Allocations after starting the application then nothing is logged!

You could log everything from the start of the game but I found the graphs just far too confusing to read if I tried to do that.

When you have played enough of the game to get some data, skip back to the CLR Profiler window and 'Kill Application'.

For my purposes I can now ignore everything except the 'Allocation Graph'.  Open that up and skip to the RIGHT hand end.  This is the biggest tip I can give.  You work backwards from the right hand end towards the left hand end.

Start at the largest allocations at the top right.

Sometimes you can easily follow the lines but when they get lost in the others, either increase the scale or just click on any one of the boxes in the line and the lines change to a cross hatching either side to make them easier to follow.  You can also double click a method to see the connecting methods either side.
Just work backwards from method to method until you recognise a method in your code.

So far I have found the changes necessary to avoid the garbage have been quite minor.  Most of my own allocations have been caused by List<T>.AddRange(...) where <T> is one of my own classes.  This is easy to fix by using a loop instead of the built in AddRange().

I have had one where it was caused by an internal XNA framework method but luckily I did not need to be doing that during the game, so I simply paused its update during game and restarted whenever the menus open.

I'm now left with a few tiny allocations that I have to go through one at a time to eliminate them.  Then I can enjoy testing again on the Xbox 360 to have a garbage collection free game, I hope.

==

EDIT:
Just came across a tutorial that explains how to use the timeline to only look at allocations over a given period.  This saves having to activate the profiling mid game:
http://spacedjase.com/post/2010/07/02/How-to-eliminate-frame-by-frame-Garbage-Generation-using-CLR-Profiler.aspx

CLR Profiler

I should be creating levels but I've been distracted.  As I was running through them I kept getting stuck on the structures!  Mainly in tight door ways and similar small spaces.  This was spoiling the levels so I had to do something about it.

You may wonder what this has to do with the CLR Profiler.  Well I'll get there in a minute.

I needed to have a more detailed collision model for use during movement.  I already know my current method cannot be any more detailed because then it runs too slowly on the Xbox!

To solve that problem I have been working on a new design.  After a few optimisations to speed up loading I think the idea is workable on the Xbox.  In the process of testing on the Xbox I further got distracted by the garbage collection. 


Garbage collections appeared to be getting more frequest yet I am very careful when creating methods to avoid allocating memory.  I decided I needed to find out what I had overlooked before I got too far with a design that might make it worse!  This is what brings me on to the CLR Profiler.


I know that the CLR Profiler is the tool for finding out what allocates memory on the heap, which is what ultimately triggers the distracting garbage collection.  The trouble is I have always failed to get it to work.

I gave it another chance this weekend and at last I have useful results from it.

This is what I needed to do to get it to work for me:

Get version 4 of the CLRProfiler:

http://www.microsoft.com/en-us/download/details.aspx?id=16273
I suspect that this was the most important thing.

Then Read the Manual:

It comes with it and in the FAQ's it explains that if you are profiling a 32 bit app, even on a 64 bit system you must use the 32 bit profiler NOT the 64 bit profiler.
XNA games are all 32 bit.
Up until I read that, the profiler never started profiling!
As soon as I started using the 32 bit version it started to log results.  Easy if you read the last few pages of the manual!!!!!

The CLR Profiler comes in a compressed file and you can unzip it to anywhere.  After having done that I created a folder and copied the 32 bit binaries and DLLs in to a more convenient location.

Run As Administrator:

I created myself a shortcut and in the Advanced properties set the shortcut to Run As Administrator.  That saves a bit of time each time I run it.

Start In The Game Executable Folder:

Another important bit, for my game at least, is to set the 'Start In' folder in the shortcut to be the folder containing the executable of whatever game I need to profile. 

My game threw an exception because it could not find a folder it needed.  Changing the 'Start In' folder fixed that.

I didn't do those things immediately it took me a little while to work out what I had to do to get it to work.

Getting The Results

I can now run the CLRProfiler from the shortcut, select Start Application and then browse to the executable and run.  Play the game and when I exit I get some results.

Initially I was getting far too many results because all the level loading gets in the way.  I find the results easier to understand if I start profiling when I get well within the main game. 

Simply remove the tick from 'Profiling active' then start the game using the Start Application button.  My debug version already had a way to pause so I can swap applications.  I use the alt key to pause and bring up a test menu.  That was useful to enable me to skip to the profiler and tick the 'Profiling active' to start.  Play the game a bit then skip back and use 'Kill Application' to end.

The log files come up and...  now I have a lot of confusing data to understand.

Luckily there are several other sites I have been reading to learn what the results mean:
http://www.flatredball.com/frb/docs/index.php?title=FlatRedBallXna:Tutorials:CLR_Profiler
http://geekswithblogs.net/robp/archive/2009/03/13/speedy-c-part-4-using---and-understanding---clr.aspx

Now I can try to make some changes to my code to reduce the garbage collections.

AI Behaviour Tree

It has taken me a couple of weeks to get the Behaviour Tree processing up and running.  I still don't know how effective my artificial intelligence (AI) will be but the mechanism for controlling it is now in place and appears to work.

I am pleased with the design:

• Runs in a separate thread (separate hardware thread on the Xbox)
• Shares processing fairly between all the AI controlled entities (Bots)
• Unlimited levels of child behaviours
• Parallel behaviours

It is the ability to add parallel tasks that I needed.  I got stuck at that point with my earlier state machine version.

The problem I had with the state machine was that a Bot may wander about and while wandering needs to be able to look out for enemies in the area.  In addition when the Bot enters combat it needs to be able to shoot at a target while running for cover.  In this Behaviour Tree design the behaviour can replace its own parent behaviour or launch a new behaviour to enter combat. That combat behaviour then launches two more behaviours, one to shoot at a target and the other to decide where to move to.

Each behaviour is a separate class so I have things like, Hide, Chase, Evade, Combat, Find something to do, Wander, etc.  I had to create twelve separate behaviours before I could even test it.  This is because so many of the behaviours are made up of other behaviours and so few actually control the Bot.

To avoid creating garbage** I had to design the structures and classes carefully.  I finished by having only one instance of each behaviour shared by all the Bot classes.  Instead of adding the behaviours as needed and using the individual behaviour classes to store results, the results are passed in to and returned from the behaviour classes.  The results being stored between updates within their respective Bot's class'.

This image shows a simplified version of the design:

I have added a method to show on screen what any individual Bot is thinking.  I have this running in the game and I can see that the Bots respond to changes in the environment by changing their behaviour.

At the moment some of the behaviours themselves are not carrying out the actions that I would like but as each one is now independent and broken down in to smaller and smaller behaviours I can work through them to adjust each in turn to get the results I want.

==

** Garbage is the term used for adding and then freeing up memory on the heap.  This freed up memory needs to be collected for re-use by a framework process that is relatively slow on the Xbox. Just adding to the heap is eventually sufficient to trigger the slow collection process even if there is no memory available to free up.