Need help fixing / optimizing rendering

[MattStevens]

I started having a really strange issue with the FPS of my game. I'm using 1.7.2, pretty much default build. The framerate is spiking every 4 or 5 frames, making the game looks really silly. To debug this issue I launched NVPerfHUD but I do not seem to find the issue. Here's a screenshot of my debug info and you can see the obvious spiking (bottom diagram, yellow line is the time per frame (in ms)). If you are wondering, this is a close-up of an ocean. I don't know where to start looking to understand and fix this issue. Any help is welcomed.



- Matt

[Jabberwocky]

If I were in your shoes, I'd do two things.

1. Make sure it's a problem with your ogre app, and not that specific computer.

I'd run the app on other machines, and see if the behaviour is reproduced on other machines.

2. Do some performance testing to find out what code is causing the problem.

This is what perf testing software is for. It can be kind of expensive, but you might even get away with a free 1-month trial to solve your problem.

Alternatively, you can just insert timer code directly into your code base, for free.
Here's some example timer code I use.
IMPORTANT: I have not cleaned it up for general use. You'll need to edit it to make it compile. But it might help as a base for your own code if you need it.

Code: Select all

class TimerDiagnostics
{
public:
   TimerDiagnostics();

   unsigned long m_msStartTime;
   unsigned long m_msElapsed;
   unsigned long m_msHitchTime;
   unsigned long m_msHitchLength;
};

class DiagnosticsSystem
{
   // ... <snip> ...

public:
   // This is used to gather stats on how long per-tick operations take,
   // like physics or graphics.
   // You can use this to measure anything, as long as you make sure to call
   // StartTime and StopTime together in pairs.
   void StartTimer( const String& i_strID );
   void StopTimer( const String& i_strID );
   void SetDisplayTimerDiagnostics( bool i_bDisplay );
   String FormatTimerDiagnostics() const;

private:
   std::map< String, TimerDiagnostics > m_mapTimerDiagnostics;
   bool m_bDisplayTimerDiagnostics;

Code: Select all

void DiagnosticsSystem::StartTimer( const String& i_strID )
{
   // Don't bother unless we've enabled timer diagnostics.
   if ( !m_bDisplayTimerDiagnostics )
   {
      return;
   }

   std::map< String, TimerDiagnostics >::iterator it = m_mapTimerDiagnostics.find( i_strID );

   if ( it == m_mapTimerDiagnostics.end() )
   {
      TimerDiagnostics diag;
      // The following GetTimer function returns an Ogre::Timer
      diag.m_msStartTime = TimeSys()->GetTimer().getMillisecondsCPU();
      m_mapTimerDiagnostics[ i_strID ] = diag;
   }

   else
   {
      TimerDiagnostics& diag = it->second;
      diag.m_msStartTime = TimeSys()->GetTimer().getMillisecondsCPU();
   }
}


void DiagnosticsSystem::StopTimer( const String& i_strID )
{
   // Don't bother unless we've enabled timer diagnostics.
   if ( !m_bDisplayTimerDiagnostics )
   {
      return;
   }

   std::map< String, TimerDiagnostics >::iterator it = m_mapTimerDiagnostics.find( i_strID );

   if ( it == m_mapTimerDiagnostics.end() )
   {
      // This could happen if we've enabled timer diagnostics in between a StartTimer and
      // StopTimer call.  We'll just ignore this StopTimer call, and things will work out
      // next frame.
      return;
   }

   unsigned long msNow = TimeSys()->GetTimer().getMillisecondsCPU();

   // Calculate the elapsed time
   TimerDiagnostics& diag = it->second;
   diag.m_msElapsed = msNow - diag.m_msStartTime;

   // Clear out any old hitch times.
   const unsigned long msHitchClear = 2000;  // clear hitches after 2 seconds
   if ( msNow > diag.m_msHitchTime + msHitchClear )
   {
      diag.m_msHitchTime = 0;
      diag.m_msHitchLength = 0;
   }

   // Is this the longest hitch?
   if ( diag.m_msElapsed > diag.m_msHitchLength )
   {
      diag.m_msHitchLength = diag.m_msElapsed;
      diag.m_msHitchTime = msNow;
   }
}


void DiagnosticsSystem::SetDisplayTimerDiagnostics( bool i_bDisplay )
{
   m_bDisplayTimerDiagnostics = i_bDisplay;
}


String DiagnosticsSystem::FormatTimerDiagnostics() const
{
   std::stringstream ssTimer;
   ssTimer << "Timer Diagnostics" << std::endl;

   std::map< String, TimerDiagnostics >::const_iterator it = m_mapTimerDiagnostics.begin();

   for ( ; it != m_mapTimerDiagnostics.end(); ++it )
   {
      const String& strID = it->first;
      const TimerDiagnostics& diag = it->second;

      // Skip anything that is 0 ms
      if ( diag.m_msElapsed == 0 && diag.m_msHitchLength == 0 ) continue;

      ssTimer << std::setw(12) << strID << ":  t=" << std::setw(3) << diag.m_msElapsed << " h=" << std::setw(3) << diag.m_msHitchLength << std::endl;
   }

   Viewport* pViewport = CameraSys()->GetViewport();
   if ( pViewport && pViewport->getTarget() )
   {
      ssTimer << "Batch Count: " << pViewport->getTarget()->getBatchCount() << std::endl;
   }

   return ssTimer.str();
}

So now, if I want to see how long a specific section of code takes, I insert StartTimer and StopTimer calls like this:

Code: Select all

   // ...
   static String strTimerID( "Graphics" );
   DiagnosticsSys()->StartTimer( strTimerID );

   m_pOgreRoot->renderOneFrame();

   DiagnosticsSys()->StopTimer( strTimerID );
   // ...

It's generally used for code which gets called once every frame.
You can print all the current timer info using the DiagnosticsSystem::FormatTimerDiagnostics() function, say into a text UI element, or an ogre overlay.

[areay]

Thanks for sharing that Jabberwocky, I may have to turn that into a Wiki article if you don't mind

[thebluefish]

I have a similar profiling system, but using Boost's timer instead

The biggest thing I can suggest to optimize rendering is to decouple your rendering from game logic. Though it takes a bit more effort to do so, it's a very nice thing to have seperate threads for rendering and logic. Don't get thread-happy and start spawning a thread for each different task though, "logic" and "graphics" threads are really the most you need unless your game gets complicated.

[mkultra333]

I sometimes see a bit of spiking when I run my program windowed instead of fullscreen.
Another thing that might be worth checking is gpu buffer flushing. http://www.ogre3d.org/forums/viewtopic. ... ffer+flush

[saejox]

i see a lot people have their own profiling libraries.

i used to have one based on boost timer. pretty accurate, but hard to use.

then i discovered this. http://shinyprofiler.svn.sourceforge.ne ... ler/trunk/
it a C macro library. it even has a ogre interface.
so easy to use,

Code: Select all

PROFILE_FUNC();

that's it. function is now profiled.
i recommend it.

[bstone]

As long as profiling goes the simplest thing would be compiling your project with

Code: Select all

#define OGRE_PROFILING 1

then use this:

Code: Select all

void someFunction()
{
    OgreProfile( "someFunction()" );

    ... // some code

    if( condition )
    {
        OgreProfile( "someFunction(): branch 1" );
        ... // more code
    }
}

There are a few other handy macros defined in OgreProfiler.

But the last time I answered a similar question the problem was some pesky "performance improvement" application so it's the first thing to double check and get rid of.

[Knotanalt]

I'd first try to figure out if you get the same problems with other scenes, and as suggested on different computers.

Just trying to profile won't help at all for many problems. It's doubtful it's a problem with your code per se, probably either hardware or particular scene detail or something in the engine, at least that's always the case for me if I get something weird like that.

[MattStevens]

Thank you all for the input, it's very much appreciated. I forgot to mention in my first post that we are using DirectX9 renderer and I think it is important to know because related to my problem.

@Everyone: Looks like everyone has their own profiling code, hehe. We have rolled our own solution where I work as well to profile our engine. For Ogre profiling we use the already existing solution with OGRE_PROFILING, like bstone suggested. Our profiling tells me it is the rendering that causes issues (the call to Ogre::RenderWindow::update, basically the Ogre rendering of the scene). We also compiled Ogre with the define OGRE_PROFILING and the result is that the spike happens when calling IDirect3DDevice9::Present. The spike also happens every 4-5 frames or so. From what I understand, DirectX can "stack" up to 4 frames on the GPU, meaning Present will return even if the frame is not over. However, is you reach 4 stacked frames, Present will block until all of them are processed, then return for your main loop to continue, thus causing a noticable "lag spike". This would explain my issue and the spike that happens at regular intervals. This would mean that I send "too much" stuff to the graphic card and it just can't render fast enough before the next frames arrives. I never had to deal with this before and wonder if someone have experience

@Jabberwocky: The problem is present on every computer we run the software, so it's probably not driver / hardware specific. We tried multiple graphic cards and CPU / motherboard combination. The problem is persistent.

@thebluefish: Decoupling game logic and rendering is separate thread is not doable, not at the stage we are in. This is definitely something we are looking for our next engine.

@mkultra333: Software runs in full screen mode, no VSync. The actual product is supposed to run on 4 screens, however for testing we run in a single screen. The problems happens on all configuration.

@saejox: I'll look at shinyprofiler but it's probably not needed as we have our own solution already implemented.

@bstone: What exactly do you mean by "performance improvement" application. You have me confused.

@Knotanalt: We actually have 6 different "levels", the issue is only with one of them. There's a lot of differences between them, but the main one is the water with real-time reflection.

Thanks again to all of you.
- Matt

[bstone]

Here: Frame rate hiccup on Windows. That issue actually was the second time somebody used that crap

But what you say about Present() sounds like the GPU buffer flushing issue indeed. Refer to the thread mkultra333 brought up.

[MattStevens]

I read the whole thread 3 times and for some reason I kept skipping over mkultra333's link. It seems to be exactly the problem I have. I'll go over that thread to see if there's any solution to my problem.

- Matt

[Nickenstein79]

If you are using visual studio you could do an instrumentation build to get a hierarchy graph of all of the expensive function calls in your game.

I once thought my problem was rendering time, but an instrumentation build highlighted that I was accidentally updating my physics solution 3 times per frame from different frame listeners!

[MattStevens]

Problem solved!
Okay, so the issue was what I mentioned in my last post. The GPU frame buffer. It is the same problem mkultra333 had back in 2009 (! See the thread link in his post).
Sinbad made a wiki page with a single classe that fix this very specific issue. Link

I implemented the class, used with it the default number of queued frame (2) and voila, spiking is gone.

I must say the stress was at an uncomfortable level lately (software release in 5 days) and you guys really help me out. Thanks a lot to everyone.

Also, from the thread about GPU frame buffer, it seems quite a lot of people uses or needs this feature and there was talk about integrating it in the core, is it done in Ogre 1.8 or later version ? This issue is very insidious because I feel it's hard to pinpoint the reason and you need a lot of research to understand why it happens and how to fix it. Just my 2 cents.

- Matt

[bstone]

That's GPU command buffer, just for purity And it won't actually happen that often because in real life the CPU doesn't go on vacation in that many projects. Just make it do some real work and it won't get ahead of the GPU that easily. If you have lots of spare cycles in your product then it's time to add some software synthesizer with a cool audio track to keep your users entertained but your CPU busy.

[MattStevens]

Gotcha, I'll remember the exact name next time. As for the CPU idling, it is definitely not the normal case. It is only in a specific level, at a specific scene that the issue appeared, so we'll go easy on new CPU heavy features