Profiler output: Call graph

The profiler call graph provides detailed function call information.

The section "Call graph" provides the following details for each function:

  1. The functions that called it, the number of calls, and an estimation of the percentage of time spent in these functions.
  2. The functions called, the number of calls, and an estimation of the time that was spent in the subroutines called from this function.
Tip:

Runtime system internal function names start with the rts_ prefix. For example, the rts_display() function implements the DISPLAY instruction. Showing these internal functions in the profiler output is useful to analyse the code. Usually rts_* functions appear at the top of the flat profile list, because most of the processing time is spend in these runtime functions (for example to execute SQL statements). To improve your code, spot the first user function that appears in the flat profile list, and check the %self number: This is where user code can be improved.

Table 1. Call graph columns
Column name Description
index Each function has an index which appears at the beginning of its primary line.
%total Percentage of execution time spent in this function. Includes time spent in subroutines called from this function.
%self Percentage of execution time spent in this function excluding the time spent in subroutines called from this function.
%child Percentage of execution time spent in the functions called from this function.
calls/of Number of calls / Total number of calls
name Function name

Output example:

index      %total  %self  %child  calls/of	 name
...
            7.51    0.00    7.51      1/2        <-- myprog.main
           21.10    2.64   18.46      1/2        <-- myprog.fB
[6]        28.60    2.64   25.96        2        *** myprog.fC
           25.96    4.46   21.50      7/8        --> mymod.fA

Description:

  • The index [6] corresponds to the line in the top "Flat profile" output.
  • The three stars *** indicate the function that is analyzed: myprog.fC.
  • The myprog.fC function has consumed 28.60% of the execution time (%total column):
    • 2.64% of the execution time is spent in the current function code (%self column)
    • 25.96% of the execution time is spent in the called functions (%child column)
  • The myprog.fC function has been called 2 times in the program (%calls/of column)
  • The myprog.fC function has called the mymod.fA function 7 times, on a total of 8 calls in the whole program.