Help reading TGB profiler output, please !
by Blake Drolson · in Torque Game Builder · 05/24/2011 (7:46 pm) · 5 replies
Aloha,
So I am trying to get a handle on why my games performance dips down when we turn up the crazyness. Yes I know more crazyness usually means we are doing too much, but we want as much crazyness in our game as possible without having any low frame rates, so this means I have been doing profiling of our code in order to understand how the game is spending its time as it changes from high frame rates to low ones.
I have done some work profiling the script code using the methods talked about here....
www.garagegames.com/community/forums/viewthread/119675
This has been very helpful, but now I also realize I wanted to look at the time spent by the underlying engine. Ok now I found the profilerenable() call and the profilerdump() calls. But what I now want to know if what does this output mean. I am having trouble finding docs covering the profiler output in detail.
I have three questions about reading the output.
1) What do the column names o the first section of output mean? I see this...
%NSTime % Time Invoke # Name
What is %NSTime, what is %time and what is invoke? I have guesses, anyone know for sure?
2) The second section is hierarchal , how is this ordered and what does it mean exactly?
3) Is there a way to tell from the profiler how much time is spent in the script code overall, specific script code classes, and how much is spent doing things like particle effects?
Thank you very much in advance for any help.
So I am trying to get a handle on why my games performance dips down when we turn up the crazyness. Yes I know more crazyness usually means we are doing too much, but we want as much crazyness in our game as possible without having any low frame rates, so this means I have been doing profiling of our code in order to understand how the game is spending its time as it changes from high frame rates to low ones.
I have done some work profiling the script code using the methods talked about here....
www.garagegames.com/community/forums/viewthread/119675
This has been very helpful, but now I also realize I wanted to look at the time spent by the underlying engine. Ok now I found the profilerenable() call and the profilerdump() calls. But what I now want to know if what does this output mean. I am having trouble finding docs covering the profiler output in detail.
I have three questions about reading the output.
1) What do the column names o the first section of output mean? I see this...
%NSTime % Time Invoke # Name
What is %NSTime, what is %time and what is invoke? I have guesses, anyone know for sure?
2) The second section is hierarchal , how is this ordered and what does it mean exactly?
3) Is there a way to tell from the profiler how much time is spent in the script code overall, specific script code classes, and how much is spent doing things like particle effects?
Thank you very much in advance for any help.
#2
The %NSTime, and %time, are they listed in terms of the percentage of the total frame time? What if I want to know how long in milliseconds those functions took? Should I calculate the total time for the frame and then multiply by percentage to get total elapsed time for that function?
I ask as I am trying to get a handle on changing frame rates and what is causing slowdowns at certain points in gameplay. Wonder if percentages all grow evenly as frames get longer or if I can spot the issue from changing percentage spreads.
05/27/2011 (4:06 pm)
Thank you very much for your reply Rene, that was very helpful. One more question if I might.The %NSTime, and %time, are they listed in terms of the percentage of the total frame time? What if I want to know how long in milliseconds those functions took? Should I calculate the total time for the frame and then multiply by percentage to get total elapsed time for that function?
I ask as I am trying to get a handle on changing frame rates and what is causing slowdowns at certain points in gameplay. Wonder if percentages all grow evenly as frames get longer or if I can spot the issue from changing percentage spreads.
#3
Actually, the total execution time isn't really overly useful. What is interesting in profiling is how long something executes relative to something else. So, for example, if you profile for N seconds and it turns out that 80% of those N seconds are taken up by function X() itself, then that function clearly is a bottleneck.
Go to the gameplay section where you see the slowdown happening and then immediately before, start the profile. Then go through the section and immediately afterwards, stop profiling. Then you have a nice profile of that section alone.
In T3D, and I believe in TGB/TGEA/TGE too, there is a handy function doProfile() that's bound to "CTRL+F3" by default. So, you press "CTRL+F3", it resets everything and then profiles for as long as you hold down the key combination.
This allows to very easily profile certain aspects of gameplay.
05/27/2011 (4:26 pm)
The timing always refers to the period over which you are profiling the beginning of which is marked by the time profilerReset() is called (which resets all counters back to zero). All output of those timings is in percentages relative to that period of time.Quote:What if I want to know how long in milliseconds those functions took? Should I calculate the total time for the frame and then multiply by percentage to get total elapsed time for that function?
Actually, the total execution time isn't really overly useful. What is interesting in profiling is how long something executes relative to something else. So, for example, if you profile for N seconds and it turns out that 80% of those N seconds are taken up by function X() itself, then that function clearly is a bottleneck.
Quote:I ask as I am trying to get a handle on changing frame rates and what is causing slowdowns at certain points in gameplay. Wonder if percentages all grow evenly as frames get longer or if I can spot the issue from changing percentage spreads.
Go to the gameplay section where you see the slowdown happening and then immediately before, start the profile. Then go through the section and immediately afterwards, stop profiling. Then you have a nice profile of that section alone.
In T3D, and I believe in TGB/TGEA/TGE too, there is a handy function doProfile() that's bound to "CTRL+F3" by default. So, you press "CTRL+F3", it resets everything and then profiles for as long as you hold down the key combination.
This allows to very easily profile certain aspects of gameplay.
#4
05/27/2011 (5:00 pm)
Thank you Rene, super info, very appreciated. 
#5
05/29/2011 (8:38 am)
*edit... wrong thread. :) 
Associate Rene Damm
NSTime means non-sub time. This is a bit of a very odd kind of naming. The usual name applied to this in other profilers is "self time", i.e. the time that is spent executing that profiling scope but not including time spent on profiling scopes that execute within that scope.
Put simply, if you profile function f() and it calls g(), then the self time (NSTime) is the time spent executing f() minus the time spent on executing g().
It gives you a call graph, i.e. while the first section just shows you the raw execution times of each profiling scope (sorted by self time), the second section shows you what each such scope did exactly and how it breaks apart into other scopes that it executed while it was active.
For that, you usually need to hunt for the respective profile scopes in the code. Put a new scope in compiledEval.cc/cpp to profile time spent running script code (probably only self time will be of interest here as the total time will include lots of stuff that is triggered through scripts).