Profiler

… we see that it was called 3 times, once from each of loop10000(), loop20000(), loop30000(), and that it in turn called the internal function rts_for_init() to initialise a for loop 3 times.  The percentages relate to the calls to/from the listed functions.

What this can tell is if the function is being called with a bad set of arguments that lead to it taking a long time.  In this example, we can see that when loop() is called from loop30000() it is taking approximately 3 times as long to process as it did when called from loop10000() which given the parameters is not surprising.

Analysis

Some things to observe in the results …

• the results for MAIN block are shown by the entry “main” (deep down FUNCTION main() = MAIN)
• names beginning < builtin > are internal functions and won’t be a FUNCTION in the code
• time spent waiting for user input is ignored
• the percentages are a percentage of total time.  If you improve the results for an individual function, its total percentage will decrease and you would expect totals for other functions to increase
• the results are sorted by value in the %self column, hence any potential improvement will likely be found in the results at the top of each section and you can invest your time there
• the %self column should add upto 100% in the Flat Profile
• there will be a little bit of variation and it is unlikely you will get the same results twice

As the profiler measures time spent in functions and not lines of code, you may get better analysis if you break long functions into several smaller functions so that you get a result for each of these smaller functions.  For instance wrapping CONNECT inside a function is a good idea if you want to analyse that time as a database connection often takes some time.

Note that the time spent waiting for user input is ignored, i.e. time spent waiting for the user to respond in INPUT, MENU and other dialog statements is ignored.  However you should note that time spent waiting for the operating system, database, front-end initialisation, web services is not ignored.  So you should be aware of this when analysing results.

To mitigate against database caching, one thing I might do is to run the program under test twice in quick succession, or I might add a function at the beginning of the program that selects the data required into dummy variables.  The idea being to force the data into the database cache and not have the results clouded by the data being read from disk rather than being read from the database cache.

The GUI connection also takes some time.  This can be demonstrated by running the profiler with  $FGLDIR/demo/demo and exiting the program straight away.  The function that takes most of the time is rts_optionsSet which coincides with the OPTIONS INPUT WRAP which is the first bit of UI in that program.  This first bit of UI is where the GUI connection and initialisation is occurring.  If you add a ui.Interface.refresh() immediately before that and run the profiler again you will see that the ui.Interface.refresh() is now consuming the time as that is now the first bit of UI.

What this last point means is that you may find it beneficial to create test programs to test individual functions or processes.  These programs can be run with no GUI interface (FGLGUI=0) and the results won’t be clouded with time spent connecting to the GUI.

Summary

You can read more about the profiler in the documentation.  It is a useful tool to analyse where time is being spent by a Genero program and make your programs more efficient.

As a final tidbit, run the following in the profiler and guess beforehand how many times is loop_start() and loop_end() called? …

MAIN
    DEFINE i INTEGER
    FOR i = loop_start() TO loop_end()
    END FOR
END MAIN

FUNCTION loop_start()
    RETURN 1
END FUNCTION

FUNCTION loop_end()
    RETURN 10
END FUNCTION

… check your answer in the profiler output, loop_start() will be called once, loop_end() will be called 11 times, the number of iterations + 1.  What this will tell you is that if the end expression of a loop never changes, why evaluate it on each iteration of a for loop?  It maybe beneficial to evaluate the end expression once before the loop.

Run the following in the profiler and guess beforehand how many times b() will be called …

--OPTIONS SHORT CIRCUIT

MAIN
    IF a() AND b() THEN
        DISPLAY "TRUE"
    ELSE
        DISPLAY "FALSE"
    END IF
END MAIN

FUNCTION a()
    RETURN FALSE
END FUNCTION

FUNCTION b()
    RETURN TRUE
END FUNCTION

… answer is 1, now repeat after uncommenting the OPTIONS SHORT CIRCUIT. and you should observe that b() is no longer called.  That is, it won’t be evaluated unnecessarily.

You can use the profiler like this to justify programming techniques so open your eyes to using it with small test programs and experiments, as well as analysing complete programs.