FPS hiccups profiling

Discussion area about developing or extending OGRE, adding plugins for it or building applications on it. No newbie questions please, use the Help forum for that.
User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 4:02 pm

I have been working in the last few weeks on a very annoying issue, a project I am working on suffers from hiccups – meaning frame loss every few frames, a random frame each let's say 300 frames. I didn't know if the problem is a CPU or a GPU issue – or perhaps both. I wanted statistics of code bottlenecks – but only of the problematic frames, the ones that take too long (the hiccup ones). I didn't find any existing tool\code to give me that information. So I decided to create some sort of profiling tool – to answer that question.

I researched using Google, and found this great piece of code:
http://floodyberry.wordpress.com/2009/1 ... profiling/

The nice thing about this code is that it is easy to use and gives you a good report that includes the full call stack of the bottlenecks, and more impotently – you can define exactly what part of the code to profile. You need to add a macro def to the start of each function you want to profile – and when you close the program – you get an HTML table of the bottlenecks. (You can also start and stop+get the report in in the middle of the program execution if needed).
That was very helpful to find bottlenecks, but not the special "FPS hiccups" bottlenecks.

I improved the code (modified code is attached to this post).
My idea is to store the statistics of each frame on the side – and at the end of the frame – if the frame takes longer than a predefined time – add it to "hiccups statistics", in any case – clear the bucket each frame.
This really helped me out and I was able to find the reasons for the hiccups.

The way to use it is such:
I defined __PROFILER_ENABLED__
I call PROFILE_START_PROFILING at the beginning.
I call PROFILE_DUMP_REPORT_AS_HTML at the end.
At each frame end I check how long it took and call PROFILE_ADD_TO_HICCUP_STAT or PROFILE_ADD_TO_NOT_HICCUP_STAT accordingly.

I needed to add PROFILE_SCOPED(); at the beginning of each of the function I wanted to profile, this was a lot of effort.

If we want to add built in support for this profiler in OGRE we will need to add some "OGRE_START_FUNCTION" macro or the sort to all of our function – making the code dirty, but also easier to profile.

This work is far from being complete, but it is a nice start and useful in many cases.

BTW: Everything here is currently windows only, 32 bit.

That’s about it, what do you think? Useful? Should we add it to OGRE in any way? Should we add all the function start macros?
Attachments
code.zip
My modified version of the original code.
(11.96 KiB) Downloaded 99 times
0 x
Watch out for my OGRE related tweets here.

PhilipLB
Google Summer of Code Student
Google Summer of Code Student
Posts: 550
Joined: Thu Jun 04, 2009 5:07 pm
Location: Berlin

Re: FPS hiccups profiling

Post by PhilipLB » Thu Feb 07, 2013 4:14 pm

This sounds very interesting. Have you found out, where the hickups are coming from?
0 x
Google Summer of Code 2012 Student
Topic: "Volume Rendering with LOD aimed at terrain"
Project links: Project thread, WIKI page, Code fork for the project
Mentor: Mattan Furst


Volume GFX, accepting donations.

bstone
OGRE Expert User
OGRE Expert User
Posts: 1920
Joined: Sun Feb 19, 2012 9:24 pm
Location: Russia

Re: FPS hiccups profiling

Post by bstone » Thu Feb 07, 2013 4:32 pm

My experience is that adding those macros to all functions/methods will mess up the code big time, especially inline functions. Since looking at the code is what you usually do much more often than profiling, that might become a real hassle.

I usually add it from scratch every time I'm seriously puzzled with something like you've been tackling. But I start with a few places at the top level, then narrow it down by descending into potentially problematic places based on the gathered stats from the previous modification.
0 x

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 4:41 pm

@PhilipLB: Yes, an issue with the RTSS and my terrain engine - it keep creating shaders, Mattan has an idea to create a template system to overcame that issue, but my solution is good for any code project.

@bstone: I agree with you, but if you really don't like it - you can always "replace all XXX_MACRO" with nothing - then get back the clean code, profiling and dealing with bottlenecks in gaming is such a big part of the work, so it may be a price we should pay (adding the macro).
0 x
Watch out for my OGRE related tweets here.

bstone
OGRE Expert User
OGRE Expert User
Posts: 1920
Joined: Sun Feb 19, 2012 9:24 pm
Location: Russia

Re: FPS hiccups profiling

Post by bstone » Thu Feb 07, 2013 4:57 pm

Maybe rework PROFILE_SCOPED() into something that could use /Gh and /GH Visual C++ compiler options? I guess GCC should have something like that too. Should be easy - have a vector working like a stack container somewhere and put those suckers on that stack in _penter(), then remove in _pexit(). That will preserve the logic. The stack dump will have an extra call but that's minor.
0 x

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 5:09 pm

No clue - I use visual studio and may be limited because of it.
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 5:10 pm

Perhaps some program that will add the macro to the source - and you will use it only when profiling...
0 x
Watch out for my OGRE related tweets here.

User avatar
Mikachu
Gnoll
Posts: 603
Joined: Thu Jul 28, 2005 4:11 pm
Location: Nice, France

Re: FPS hiccups profiling

Post by Mikachu » Thu Feb 07, 2013 5:21 pm

Assaf Raman wrote:Perhaps some program that will add the macro to the source - and you will use it only when profiling...
Things are getting interesting! :D

I was about to suggest the same thing, but thought it would be too complex.

Maybe it's time to see what libclang is able to do in this field? (like getting the position in source code of each function implementation?)
Or maybe a naive parser would just be enough for that..
0 x
OgreProcedural - Procedural Geometry for Ogre3D

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 5:32 pm

Well, in OGRE our functions definitions have some coding standard, it may be easy to fix the code where the coding standard is not like the rest - then write a simple program that finds the next "{" after each

Code: Select all

//-------------------------------------
in the code...

You get the idea...
0 x
Watch out for my OGRE related tweets here.

bstone
OGRE Expert User
OGRE Expert User
Posts: 1920
Joined: Sun Feb 19, 2012 9:24 pm
Location: Russia

Re: FPS hiccups profiling

Post by bstone » Thu Feb 07, 2013 5:35 pm

Assaf Raman wrote:No clue - I use visual studio and may be limited because of it.
I proposed that exactly for Visual C++ which is what Visual Studio uses. The /Gh switch will make Visual C++ inject a call to _penter() at the start of every function generated by the compiler, /GH will make a call to _pexit() at the function exit. _penter/_pexit are user defined functions.

I didn't touch GCC for quite a while but quick googling tells me that it has the -finstrument-functions switch that exposes the same functionality. So that might be a good solution after all.
0 x

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Thu Feb 07, 2013 6:43 pm

Wow - nice - this can be the best solution! Thanks for posting, I will try it out.
0 x
Watch out for my OGRE related tweets here.

User avatar
mkultra333
Gold Sponsor
Gold Sponsor
Posts: 1889
Joined: Sun Mar 08, 2009 5:25 am
x 36

Re: FPS hiccups profiling

Post by mkultra333 » Fri Feb 08, 2013 4:05 am

It's not the GPU command buffer, is it? Might be worth testing.
0 x
"In theory there is no difference between practice and theory. In practice, there is." - Psychology Textbook.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Fri Feb 08, 2013 12:10 pm

What do you mean? How?
0 x
Watch out for my OGRE related tweets here.

User avatar
mkultra333
Gold Sponsor
Gold Sponsor
Posts: 1889
Joined: Sun Mar 08, 2009 5:25 am
x 36

Re: FPS hiccups profiling

Post by mkultra333 » Fri Feb 08, 2013 3:59 pm

I've posted before about the GPU command buffer and the problems that it can cause and, with tweaking, problems it can fix. http://www.ogre3d.org/forums/viewtopic.php?f=5&t=50486
Tweaking the number of buffers has let me solve problems with input lag on a one card system, erratic framerates on a dual card SLI system, and 3DVision culling issues on a stereoscopic SLI system. (Short version: 2 buffered frames worked better than the default 3).

Perhaps more relevant to your issue, this user had a problem with frame rate spikes that was traced to the GPU command buffer. http://www.ogre3d.org/forums/viewtopic.php?f=2&t=74307

Not saying this is your issue, I don't know, just thought I'd mention it since the GPU command buffer can sometimes play havoc with framerates. At the very least, maybe it'd be interesting to see what happens if you set the GPU buffers to just one. Performance would go downhill, but it might help trace where the missing frame happens, since you'll have a nice one-to-one link between the CPU telling a frame to render and actually having the GPU render it.
0 x
"In theory there is no difference between practice and theory. In practice, there is." - Psychology Textbook.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Fri Feb 08, 2013 5:42 pm

Thanks, will have a look.
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 10:37 am

Regarding the _penter Hook Function - I am having issues getting the calling function name.
Looking into the solutions suggested here:
http://stackoverflow.com/questions/2281 ... -a-project
0 x
Watch out for my OGRE related tweets here.

bstone
OGRE Expert User
OGRE Expert User
Posts: 1920
Joined: Sun Feb 19, 2012 9:24 pm
Location: Russia

Re: FPS hiccups profiling

Post by bstone » Mon Feb 11, 2013 11:59 am

Hmm. I thought the profiling code you used analyzed the call stack. Does it still need the calling function name?
0 x

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 12:32 pm

0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 1:04 pm

The code I used - uses the __FUNCTION__ predefined macro to get current function name.
The downside is that I need to add a macro to all my function - making my code dirty - and also a lot of work.
I wanted to use the /Gh (Enable _penter Hook Function) compiler option - but it doesn't give you the function name (the gcc equivalent does give you a parameter you can use to find out the calling function).
I found this article: "A Simple Profiler using the Visual Studio C/C++ Compiler and DIA SDK" - that includes a mix of assembly and the DIA SDK to get the calling function name.
This is great - because I think I can mix it into the code I used - to get the same nice result - but without having to add so much macros to all my code.

Will try to merge both code bases now.
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 5:21 pm

Got it to work on a sample project (code is dirty - but it works) - attached.
Will now try to use on OGRE.
Attachments
ProfilerTest.zip
(27.68 KiB) Downloaded 80 times
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 6:14 pm

Got this basically to work with the sample browser (didn't call PROFILE_ADD_TO_HICCUP_STAT yet) - attached is a first sample file (call stack also doesn't work for now).
Attachments
no-info-given-profile-20130211_191111.zip
(34.18 KiB) Downloaded 95 times
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 6:30 pm

Sec, seems that I missed that cmake removed my "/Gh /GH " flags, recompiling and retrying.
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 6:45 pm

Call stack does- you just need to add the img folder to the same folder as the HTML report.
Attachments
img.zip
(2.36 KiB) Downloaded 84 times
0 x
Watch out for my OGRE related tweets here.

User avatar
Assaf Raman
OGRE Team Member
OGRE Team Member
Posts: 3092
Joined: Tue Apr 11, 2006 3:58 pm
Location: TLV, Israel

Re: FPS hiccups profiling

Post by Assaf Raman » Mon Feb 11, 2013 6:51 pm

I was able to create a full report of the OGRE sample browser, sort of a big file.
Hard to find a browser that will open such a big HTML file...
Here it is: https://docs.google.com/file/d/0BzHCK1h ... sp=sharing

I guess I need to work on formatting the HTML to a few files with some javascript magic to load them on request.
Will love ideas.
A new tool to view the result?
0 x
Watch out for my OGRE related tweets here.

al2950
OGRE Expert User
OGRE Expert User
Posts: 1210
Joined: Thu Dec 11, 2008 7:56 pm
Location: Bristol, UK
x 80

Re: FPS hiccups profiling

Post by al2950 » Mon Feb 11, 2013 7:20 pm

A have been following this post with interest. Looks really good so far, although chrome gave up on the 2GB html file! Will have a closer look when I get home.

Nice work! :D
0 x

Post Reply