How do I interpret the differences between the "Time" and "Self" columns in Unity's profiler?

Question

I'm not quite understanding how to read the results of the profiler:

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.

UPDATE:

A:

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.

B:

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] ).

    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;
}

Answer 1

"Total" represents the overall cost of the function (in milliseconds or percentage, depending on the column). "Self" represents the cost of that function minus the cost of all child functions.

In other words, the answer to...

where is all the time being spent coming from?

...is "all the code that isn't a function call."

In this case the "culprit" is probably the loop itself. This doesn't mean the loop is slow, it means a large part of the cost of that function is the loop it contains, which contains a (gated) inner loop and a bunch of non-function call computations. That inner loop is also where you call another high-cost function (PolyContainsPoint.ContainsPoint)

You should probably focus your optimization efforts on: - reducing the number of times the outer loop has to iterate - reducing the number of times the inner loop has to iterate or increasing the number of times the inner loop can be skipped entirely - reducing calls to or or optimizing PolyContainsPoint.ContainsPoint.