koobas.hobune.stream
Reading Profiler Results
I'm not quite understanding how to read the results of the Profiler:
So a method "Pathfinding_NodeAdjuster.CheckSpecificArea()" method is using up 94.7% of the "BehaviorUpdate" overall time, while taking 73.4% of that time on itself (taking ~74ms of actual time) excluding other function calls. What I don't understand is where this 74ms time is coming from.
Now I realize that if I averaged the time for all 1221 calls of this method, I would probably end up with ~74ms of time spent. But what is that time being spent on? I would have suspected GetComponent() / adding and clearing the List / something like that. But those are listed separately and only combine to get a few ms of time between them. So, where is all the time being spent coming from?
I've included the method in question, if you want more info just let me know. Any ideas are appreciated.
private bool CheckSpecificArea(List<GraphUpdateScene> gusAreaToCheck, GraphNode gn)
{
for (int areaCounter = 0; areaCounter < gusAreaToCheck.Count; areaCounter++) //check node location against each area of a certain type
{
if(nodeXZValues.x >= gusAreaToCheck[areaCounter].transform.GetComponent<Renderer>().bounds.min.x && nodeXZValues.x <= gusAreaToCheck[areaCounter].transform.GetComponent<Renderer>().bounds.max.x &&
nodeXZValues.y >= gusAreaToCheck[areaCounter].transform.GetComponent<Renderer>().bounds.min.z && nodeXZValues.y <= gusAreaToCheck[areaCounter].transform.GetComponent<Renderer>().bounds.max.z)
//basic bounds test to see if point could possibly be contained within the area before doing more advanced test (remember XY is really XZ).
{
gusPointList.Clear(); //prevent stacking.
for (int i = 0; i < gusAreaToCheck[areaCounter].points.Length; i++) //for each polygon shape's nodes
{
gusNodeXZValues.x = gusAreaToCheck[areaCounter].points[i].x;
gusNodeXZValues.y = gusAreaToCheck[areaCounter].points[i].z;
gusPointList.Add(gusNodeXZValues);
}
if (PolyContainsPoint.ContainsPoint(gusPointList, nodeXZValues)) //needs GUS objects to use WORLD SPACE!!
{
gn.Tag = (uint)gusAreaToCheck[areaCounter].areaType; //set node tag value to the value of the GUS containing said point.
return true;
}
else
{
#if DebugMaster
//Debug.Log("!PolyContainsPoint.ContainsPoint(gusPointList, nodeXZValues), NO match found");
#endif
}
}
else
{
#if DebugMaster
//Debug.Log("nodeXZValues NOT contained within renderer bounderies of: gusAreaToCheck[" + areaCounter + "], test concluded");
#endif
}
}
return false;
}
Without linking your classes and functions, we can't really deduce 100% what's going on. That said, you may want to start referencing things ahead of time, versus getting them every time you want some value. See if this speeds anything up:
private bool CheckSpecificArea(List<GraphUpdateScene> gusAreaToCheck, GraphNode gn)
{
//check node location against each area of a certain type
for (int areaCounter = 0; areaCounter < gusAreaToCheck.Count; areaCounter++)
{
// The area we want
GraphUpdateScene currentGus = gusAreaToCheck[areaCounter];
// Get the renderer ahead of time
Bounds gBounds = currentGus.transform.GetComponent<Renderer>().bounds;
// Create a rect from this
float xSize = gBounds.max.x - gBounds.min.x;
float zSize = gBounds.max.z - gBounds.min.z;
// Construct a Rect using the bounds, since that seems to be what you're checking anyway
Rect xzBoundingRect = new Rect(gBounds.min.x, gBounds.min.z, xSize, zSize);
// Get the point we're interested in
Vector2 point = new Vector2(nodeXZValues.x, nodeXZValues.y);
if(xzBoundingRect.Contains(point))
{
//prevent stacking.
gusPointList.Clear();
//for each polygon shape's nodes
for (int i = 0; i < currentGus.points.Length; i++)
{
gusNodeXZValues.x = currentGus.points[i].x;
gusNodeXZValues.y = currentGus.points[i].z;
gusPointList.Add(gusNodeXZValues);
}
//needs GUS objects to use WORLD SPACE!!
if (PolyContainsPoint.ContainsPoint(gusPointList, nodeXZValues))
{
//set node tag value to the value of the GUS containing said point.
gn.Tag = (uint)currentGus.areaType;
return true;
}
}
}
return false;
@TreyH, Thanks for the ideas, here is how things are co$$anonymous$$g along:
A:
"See if this speeds anything up" -Interesting results here: -4 GetComponents() to 1: ~90 -> ~71 [~21% overall time reduction vs original] // Component.GetComponent() 0.08 -> 0.05 Self ms. A nice improvement, good call.
4 = bounds checks into Rect.Contains(): ~90 -> ~116 [~29% time increase vs original]. // Sooo maybe not so great on this one! I'm seeing a big increase of Bounds.get_$$anonymous$$in/.get_$$anonymous$$ax [2x-3.4x more per type].
B:
What I still not sure on (and could have asked better) is:
-CheckSpecificArea() which takes 74ms, if time spent in other methods is not counted all that is left in the method is really 4 comparisons, 2 assignments, and 1 assignment with an explicit cast which are repeated. Granted that some of those sections are run a lot of times, but are those operations really that 'expensive'? I guess so.
-Changing from 4 to 1 GetComponents() saved ~20ms, but Component.GetComponent() only changed from 0.08 to 0.05, where did the time saving come from?
C:
Something else I probably should have realized sooner is that the times listed by the Profiler 'don't reflect regular operation', or in other words that the times listed also include the time needed to 'profile those scripts'.
I made my own small bit of code to profile the script during normal gameplay and Deep Profile Recording using Time.realTimeSinceStartup and realized that after isolating the 3 main sections of the script that profiling them was adding increase in processing time from ~7.7x to ~9.3x. And the Self ms times in the Profiler are even 10x longer than what my profiling code shows during Deep Profiling. All this is still logged as time needed to complete the frame (so in my case a 100ms frame is really more like 13-15ms [and probably much less] ).
I don't think 4 float comparisons should take 74ms, how many areas are you checking?
Good to know with Rect.Contains, added it for readability but clearly not worth the effort. Profiling will definitely give mixed results when running in edit mode just from the overhead involved. Have you tried profiling the process on a built project?
"I don't think 4 float comparisons should take 74ms, how many areas are you checking?"
-That is part of the problem. It isn't -really- taking that much time (probably less than one tenth of that), running Deep Profile on scripts massively increases processing time (Point C of my original reply).
That said, whatever time it is really taking is almost certainly due to the amount of times it runs (13.4k times with the current conditions). I wish there was more I could do to reduce that number (and it is a bit of a long story as to why). But it involves A* polygon clipping and not knowing which nodes will be destroyed / added /how many there will be / where they will be when the process is done. Further more because of this, the nodes must be tested in a particular order to guarantee that they are associated with 'the most correct area', and it just ends up with lots of checking.
"Have you tried profiling the process on a built project?"
-No, but as mentioned in Point C, even just using my own profiling code in edit mode (no Recording / Recording Deep) shows a huge difference. I wouldn't imagine running an actual build of the game would be much different than the Editor considering its just using 'normal code' at that point (but maybe).
