4.2 Subroutine profiling  (Page 5/6)

Fortran example

Sandwiched between each set of dashed lines is information describing a given routine and its relationship to parents and children. It is easy to tell which routinethe block represents because the name is shifted farther to the left than the others. Parents are listed above, children below. As with prof , underscores are tacked onto the labels. You may have noticed that there are two main routines: _MAIN_ and _main . In a FORTRAN program, _MAIN_ is the actual FORTRAN main routine. It’s called as a subroutine by _main , provided from a system library at link time. When you’re profiling C code, you won’t see _MAIN_ . A description of each of the columns follows:

• index You will notice that each routine name is associated with a number in brackets ( [n] ). This is a cross-reference for locating the routine elsewhere in the profile. If, for example, you were looking at the block describing _MAIN_ and wanted to know more about one of its children, say _a_ , you could find it by scanning down the left side of the page for its index, [5] .
• %time The meaning of the %time field is a little different than it was for prof . In this case it describes the percentage of time spent in this routine plus the time spent in all of its children. It gives you a quick way to determine where the busiest sections of the call graph can be found.
• self Listed in seconds, the self column has different meanings for parents, the routine in question, and its children. Starting with the middle entry — the routine itself — the self figure shows how much overall time was dedicated to the routine. In the case _b_ , for instance, this amounts to 3.23 seconds.
  Each self column entry shows the amount of time that can be attributed to calls from the parents. If you look at routine _c_ , for example, you will see that it consumed a total time of 3.23 seconds. But note that it had two parents: 1.62 seconds of the time was attributable to calls from _a_ , and 1.62 seconds to _b_ .
  For the children, the self figure shows how much time was spent executing each child due to calls from this routine. The children may have consumed more time overall, but the only time accounted for is time-attributable to calls from this routine. For example, _c_ accumulated 3.23 seconds overall, but if you look at the block describing _b_ , you see _c_ listed as a child with only 1.62 seconds. That’s the total time spent executing _c_ on behalf of _b_ .
• descendants As with the self column, figures in the descendants column have different meanings for the routine, its parents, and children. For the routine itself, it shows the number of seconds spent in all of its descendants.
  For the routine’s parents, the descendants figure describes how much time spent in the routine can be traced back to calls by each parent. Looking at routine _c_ again, you can see that of its total time, 3.23 seconds, 1.62 seconds were attributable to each of its two parents, _a_ and _b_ .
  For the children, the descendants column shows how much of the child’s time can be attributed to calls from this routine. The child may have accumulated more time overall, but the only time displayed is time associated with calls from this routine.
• calls The calls column shows the number of times each routine was invoked, as well as the distribution of those calls associated with both parents and children. Starting with the routine itself, the figure in the calls column shows the total number of entries into the routine. In situations where the routine called itself, you will also see a +n immediately appended, showing that additional n calls were made recursively.
  Parent and child figures are expressed as ratios. For the parents, the ratio m/n says “of the n times the routine was called, m of those calls came from this parent.” For the child, it says “of the n times this child was called, m of those calls came from this routine.”