Profiler Tips

When analysing slow performance of a Genero application, the Program Profiler is one tool at your disposal.  There is an earlier Ask-Reuben introducing the profiler.  The questions we get on the support desk show a lack of understanding on how it works and therefore what information you can extract.

It cannot be used to tell you if a program took more or less time to run.  Among the reasons for this  is because it excludes time spent waiting for user input.  If you want to know how long it takes to run, add a function you know takes a certain amount of time to run.  For example if you add the following into your library …

FUNCTION run_sleep1()
    RUN "sleep 1" -- replace sleep with appropriate function for your O/S
END FUNCTION

… and call that whenever you are running the profiler, then you can calculate the total time taken.  From the Flat Profile output, you can determine the total execution time with some simple maths.  If the %total of this run_sleep1() function is 25.0%, then you know that the total time is 1/0.25 = 4 seconds.

The other way to determine if improvement was successful is to note that the time spent in the other functions should be similar between runs of an application.  If a function you have modified goes from taking 40% of time to 30% then you know you have made it faster.  If a function goes from 30% to 40% then you know you have made it slower.
When you are looking for functions to improve, you should be looking at the functions that take up the most of the time that are listed at the top of the Flat Profile.  If a function only takes 1% of total time then there is limited room for improvement.  A function that takes 50% of the total time, then this is a bottle-neck and there is plenty of room for potential improvement.
The other area that catches people out is when they have a function that is called multiple times from different places with different parameters.  In the Call Graph page of the documentation there is example output that shows a  function fC being called twice …

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

… once from main and once from fB.  We can deduce that when called from fB, the arguments it passed made it took 2.6x (18/7) times more.  However what if the output was …

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

…  now there are two calls from fB to fC, which of these calls took longer?

What you can do is use the execution trace to determine what arguments are being passed to the function.  Using the environment variable FGLTRACE_FUNCTIONS to only trap calls to myprog.fC , you can determine what the arguments for each of the calls are.  Then in your code, you can add wrappers to call fC with those values.

FUNCTION fC_1()
     CALL fC("Foo")
END FUNCTION

FUNCTION fC_2()
     CALL fC("Bar")
END FUNCTION

Now you might get output of …

index      %total  %self  %child  calls/of	 name
...
            7.51    0.00    7.51      1/2        --- myprog.main
            7.51    0.64    4.46      1/1        --- myprog.fC_1
           13.69    2.00   14.00      1/1        --- myprog.fC_2 
       [6] 28.60    2.64   25.96        2        *** myprog.fC 
           25.96    4.46   21.50      7/8        --- mymod.fA

which tells you that when passing the argument “Bar”, this is calling fC to run slower.

Some other points to know with the profiler, the time spent connecting to the user interface and the license check is contained in the first UI call.  To see this, try a program like ..

MAIN
    -- OPTIONS INPUT WRAP
    CALL menu1()
    CALL menu2()
END MAIN

FUNCTION menu1()
    MENU""
        ON ACTION EXIT
            EXIT MENU
    END MENU
END FUNCTION

FUNCTION menu2()
    MENU ""
        ON ACTION EXIT
            EXIT MENU
    END MENU
END FUNCTION

… you will note that both functions to not take 50% of the time. More time is spent in the first MENU statement due to the fact the UI is initialised and the license check performed.  Uncomment the OPTIONS INPUT WRAP, this being the first piece of UI,it will now consume a large chunk of time.

So with profiler manage your expectations.  Its prime purpose is to tell you where time is being spent so you can determine where is potential for improvements to be made.