SuperProfiler to the rescue!

Thursday, February 5, 2009

SuperProfiler is a library I wrote to help us track down performance issues in Zero Gear. It is open source so anyone can use it (and hopefully help make it better!).

You simply place a piece of code at the start of any function you want to profile and SuperProfiler takes care of the rest.

An example...


void SomeFunction2(int var1)
{
    SUPER_PROFILE("void SomeFunction2(int var1)");
    var1++;
}

void SomeFunction1(void)
{
    SUPER_PROFILE("void SomeFunction1(void)");
    int lala = 2;
    SomeFunction2(1);
}

void main(void)
{
    SomeFunction1();
    SuperProfiler::TextOutput textOutput("SuperProfilerResults.txt");
    SuperProfiler::Root::OutputResults(textOutput));
}


and in SuperProfilerResults.txt is...


Function List | Total Run Time=0 | Total Profiled Function Calls=2
-----------------------------------------
void SomeFunction1(void) | Total Time=0.00 | 50.00% of time | Total Calls=1 | 50.00% of calls
void SomeFunction2(int var1) | Total Time=0.00 | 50.00% of time | Total Calls=1 | 50.00% of calls

Call Tree
-----------------------------------------
ROOT
    void SomeFunction1(void) | Avg Time=0.0000 | Times called=1
        void SomeFunction2(int var1) | Avg Time=0.0000 | Times called=1


Simple and easy. Check out the Google code site for all the juicy details.

Let me know if you find it useful!

8 comments:

Max said...

Looks nice. There's a similar library (http://shinyprofiler.sourceforge.net/) that probably could have saved some effort, but it's always nice to have your own system that's easy for you to modify.

On my last project we had something similar to this, but we also had the ability to save the profiler data for each frame, so you could go "back in time" and look at big spikes.

Brian Cronin said...

Thanks for the link Max. I hadn't seen Shiny before.

I was using http://www.cdiggins.com/profiler/ before and was not satisfied with the results. It only took me about a day and a half to write SuperProfiler so I don't feel it was time wasted (it was fun anyway, haha).

I really like your suggestion of per frame recording. I am going to get that implemented ASAP.

Once per frame recording is implemented, I think I could detect a spike just by seeing if some % of time extra was spent in this frame vs the average time of frames and flag it.

I am also working on more output methods. Just got CSV output working so we can easily visualize the function list in a spreadsheet program. Next is call tree output to XML...

Ash McConnell said...

Hi Brian,

Thanks for SuperProfile, it looks great.

I am having trouble getting it working though. The profile results are always empty.

Do you have to start the profiling from the main function level and have a SUPER_PROFILE at each level below that? I'm just wondering if my boost::functions will work correctly if that is the case?

Thanks for your help
All the best,
Ash

Brian Cronin said...

Ash, try getting the latest from SVN. I fixed a bug which might be giving you problems.

SUPER_PROFILE is just a macro that creates a local SuperProfile object which pushes and pops the stack.

You do not need to put a profile everywhere. I have one in each system and then if I notice one system is taking up too much time, I add more to different classes in that system until I find my problem. boost::functions should work fine (depending on how you are using them I suppose). Check out the included tests for some usage examples (I need to write up a proper tutorial or something...)

Ash McConnell said...

Thanks Brian,

I must be doing something silly. I updated and I am still getting blank output.

Here is how i'm using the profiler: -

- SUPER_PROFILE("MAIN()"); in the main().
- Everything below the main is a static library - I have a SUPER_PROFILE("RaceGameController::Start()"); and a SUPER_PROFILE("Update Physics"); in there (as a start)

No luck. I just get empty tags in the XML output and nothing in the plain text output.

I capture the output at the end of the main function using: -

SuperProfiler::SuperOutputXML superOutputXml("ValidTXTResults.xml");
SuperProfiler::SuperRoot::OutputResults(superOutputXml);

It seems so simple (in a good way!), I'm not sure where I could go wrong.

Thanks again - sorry to be a pain!
All the best,
Ash

Brian Cronin said...

Hmm, check the return value of OutputResults. I am guessing it is failing. The only reason it should fail now is if any profile still exists on the stack.

So this is wrong:
SUPER_PROFILE("Main()")
...
OutputResults()

While this is correct:
{
SUPER_PROFILE("Main()")
}
OutputResults()

The SUPER_PROFILEs are RAII based.

If it is still not working correctly, I suspect a linking issue between the different static libs perhaps. Can you post the snippet of code from your main?

As a side note, I would recommend not even putting a profile in main, it is going to be profiled 100% of the time since it won't be popped off the stack until the program exits.

Ash McConnell said...

Hi Brian,

That was the problem - I had the SUPER_PROFILE at the same level as the OutputResults in the main file.

I am now up and running! I may be a bit odd, but I quite like the process of optimization - although I may leave any heavy optimization to later in the project :)

Thanks again!
All the best,
Ash

Brian Cronin said...

Cool! Glad to hear you got it working!

Remember you can define SUPER_PROFILING_OFF in your project settings to turn profiling off. This is a good idea as profiling does have some cost, I haven't really measured what that cost actually is however...