Systematic Gaming

October 12, 2008

Game Profiling 102

Filed under: game programming, profiling — Tags: , — systematicgaming @ 1:41 am

In the last article we implemented a simple stopwatch, but didn’t really do much with our timing data other than print it out.  Simply printing out our timing isn’t very helpful either, first of all you can’t always see standard output on a console, and secondly it’s a pretty awkward way to collect our data, we can do much better.

Our goal this time is to design a system that allows us to profile out entire game and display the results in realtime.   We’re not going for detailed performance data, just a high level picture of our game’s performance.  The key goals are:

  • Collect data from each major subsystem
  • Present our profiling data to the user in an understandable format
  • Keep a multi-frame history of our data to detect performance spikes

Instrumentation

We’ll build on AutoTimer from the last article to meet our goals.  Our first goal is to properly collect data from various game subsystems.  Lets start with a simple sample game main loop:

do
{
   UpdateInput();
   UpdateAI();
   UpdateAnimation();
   RenderScene();
}
while (true);

We can now time each category by simply inserting one of our AutoTimers around each function.  But our goal is to collect this data and report it in a meaningful manner.  At the very least this means we’ll need to add names to our timer.  To collect and report the data meaningfully we can’t just print it out.  So lets create a profile manager to organize our data.

struct ProfileData
{
   Time totalTime;   // total time this category incurred
   Time minTime;     // maximum time this category took
   Time maxTime;     // minimum time this category took
   int totalCalls;   // number of times category was profiled
};

class ProfileManager
{
public:
   void NextFrame();

   int FindCategory(const char *name);
   ProfileData GetProfileData(int category);
   int RegisterCategory(const char *name);
   void ProfileEntry(int category, Time timeElapsed);

private:
   enum
   {
      MAX_CATEGORIES = 16,
   };

   string mCategories[MAX_CATEGORIES];
   ProfileData mData[MAX_CATEGORIES];
   int mNumCategories;  // number of categories registered
};

void ProfileManager::RegisterCategory(const char *name)
{
   assert( mNumCategories < MAX_CATEGORIES );
   int category = mNumCategories++;
   mCategories[category] = name;
   return category;
}

void ProfileManager::NextFrame()
{
   for ( int category = 0; category < MAX_CATEGORIES; category++ )
   {
      mData[category].totalCalls = 0;
      mData[category].totalTime = 0;
      mData[category].maxTime = 0;
      mData[category].minTime = MAX_TIME;
   }
}

void ProfileManager::ProfileEntry(int category, Time time)
{
   assert( category >= 0 && category < mNumCategories );

   mData[category].totalCalls++;
   mData[category].totalTime += time;
   mData[category].maxTime = max( mData[category].maxTime, time );
   mData[category].minTime = max( mData[category].minTime, time );
}

So we now have a central location to collect our data, we just have to update our timer to register with the manager, like so:

class AutoTimer
{
public:
   AutoTimer(int category) : mCategory(category)
   {
      mStartTime = GetCurrentTime();
   }

   ~AutoTimer()
   {
      Time timeElapsed = GetCurrentTime() - mStartTime;
      gProfileManager.ProfileEntry(mCategory, timeElapsed);
   }
private:
   const int mCategory;
   Time mStartTime;
};

This adds the time to our manager now instead of printing out.  We’ll have to add some code to properly register each timer too.  To keep things flexible, I’ve decided to auto-register with the profile manager, this make it easy to add new categories.  You can just as easily pre-define categories with enums, use some hash look up, or whatever.  What you do want is constant-time (ideally direct) access to the profile data or else you may find your profiling taking a lot of CPU time!

#if defined (PROFILING_ENABLED)
#define PROFILE_TIMER(category)\
static int sCategory_ ## category = gProfileManager.RegisterCategory( # category ); \
AutoTimer _timer_ ## category (sCategory);
#else
#define PROFILE_TIMER(category)
#endif

do
{
   gProfileManager.NextFrame();

   PROFILE_TIMER(Frame);
   {
      PROFILE_TIMER(Input);
      UpdateInput();
   }
   {
      PROFILE_TIMER(AI);
      UpdateAI();
   }
   {
      PROFILE_TIMER(Animation);
      UpdateAnimation();
   }
   {
      PROFILE_TIMER(Render);
      RenderScene();
   }
}
while (true);

Now we have a fully instrumented main loop, collecting our data for later usage.  We can still get our frame time easy enough too:

gProfileManager.GetProfileData( gProfileManager.FindCategory("Frame") ).totalTime

Our profiler also collects worst and best times as well as number of calls so we can compute an average.  In our instrumented loop we only track each section once, but you can see that if we profiled a commonly called function we’d also get some breakdown on how much the average call took.

Multi-Frame History

What we have now is okay if you just want to know the previous frame’s state, it will show us a game’s runtime per sub-system if the game’s CPU load is somewhat stable.  But what if our load fluctuates?  It’s pretty common for a frame rate to fluctuate for a variety of reasons, sometimes it will flutuate so that the FPS varies dramatically which is something we really shoudl be looking for and attempt to fix.

Think of a physics system – when objects are at rest the system load is quite low, but knock that stack of crates over and the processing load will increase suddenly. Also sudden, one frame spikes can occur when special events occur – adding an object to the game like when a player joins a multiplayer game.  If we’re only looking at a single frame’s time we may miss these spikes.

To help find these spikes we’ll want to keep a few frames of profiling data around – a few seconds is usually enough.  All we have to do is expand our profile manager to store or data in a circular buffer:

class ProfileManager
{
public:
   void NextFrame();

   int FindCategory(const char *name);
   ProfileData GetProfileData(int category, int frame);
   int RegisterCategory(const char *name);
   void ProfileEntry(int category, Time timeElapsed);

private:
   enum
   {
      MAX_CATEGORIES = 16,
      MAX_FRAMES = 600,  // 10 seconds at 60 fps
   };

   string mCategories[MAX_CATEGORIES];
   ProfileData mData[MAX_CATEGORIES][MAX_FRAMES];
   int mNumCategories;      // number of categories registered
   int mCurrentFrame;       // current frame to collect
};

The implementation changes are pretty straightforward, we simply increment the current frame and use the mData array as a circular buffer.

The real application is we can now display or profiling data on screen.  I find the best way is to simply draw a line graph of each major profiling category on screen, with the current frame on the left.  This gives you a nice easy to understand presentation of your data.  You can also easily see spikes, and often can identify the cause by what’s happening on screen in your game.

Summary

We’ve created a simple profile data manager which now lets us visualize our timing data.  Timing data is just one of the many datum we can collect and display, what we profile depends on what we want to know.  Similarly to how we registered with the profile manager – it’s just one possible method, with the key idea being we capture multiple frames of data from multiple sections of the game to build a picture of how our game is performing.

Visualization is also key, while I didn’t give any sample code creating a line graph from our timing data is pretty trivial.  People are very visual in nature, often a well constructed graph of data is often more useful than a chart of numbers.  However, we often still need the numbers, especially when comparing multiple runs of our game or for deeper analysis.

We now have a way to construct a high level view of our game’s performance.  In future articles we’ll look deeper into profiling methodology, and see how to use profiling data to target which parts of our game need improvement.

Advertisements

Leave a Comment »

No comments yet.

RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.

%d bloggers like this: